Debug

[samoht]

Add some debug statements. Not to merge yet.

[samoht]

I'm not sure this pull request is a good idea, but I'm trying to experiment with a minimal Log (and Stats) modules only for TCP now (before having a proper lib for the rest of Mirage).

I know some people have already expressed some interested in the right design for such a system so I'm happy to hear any feedback: /ccing @yallop @dsheets @dbuenzli

[talex5]

For the stats, it might be worth extending the Counter module in mirage-profile instead:
https://github.com/mirage/mirage-profile/blob/master/lib/counter.mli

(currently mirage-profile records the delta, which is stupid because it won't always have earlier events; it should track and record the absolute value)

[samoht]

@talex5 good idea, I'll do that.

[samoht]

@talex5 I'm not sure how to get back the counter value (which I want to display in the logs). I'll keep a separate module that we can extend later (by using mirage-profile).

[talex5]

Yes, the profile interface will need extending.

[samoht]

The idea with the new log API is the following: if you want to trace a specific module in TCP, you do:

let () =
  Tcp.(Log.enable Pcb.debug);
  Tcp.(Log.enable State.debug)

in your program.

[samoht]

Now the GC stats can be displayed, as well as the PCB state:

let () =
  let open Tcp in
  Log.enable Pcb.debug;
  Log.enable State.debug;
  Stats.Gc.enable ();
  Stats.Gc.full_major true

[samoht]

@hannesm I've added your last commit (and rebased the branch)

[samoht]

@MagnusS any idea why the tests are failing?

[samoht]

perf    0   test_tcp_iperf_two_stacks_basic.               
- I am server with IP 10.0.0.100, expecting connections on port 5001
- Manager: connect
- Manager: configuring
- Manager: Interface to 10.0.0.100 nm 255.255.255.0 gw [10.0.0.1]
- 
- ARP: sending gratuitous from 10.0.0.100
- Manager: configuration done
- I am client with IP 10.0.0.101, trying to connect to server @ 10.0.0.100:5001
- Manager: connect
- Manager: configuring
- Manager: Interface to 10.0.0.101 nm 255.255.255.0 gw [10.0.0.1]
- 
- ARP: sending gratuitous from 10.0.0.101
- ARP: updating 10.0.0.101 -> 02:50:2a:16:6d:03
- Manager: configuration done
- Iperf client: Attempting connection.
- ARP: transmitting probe -> 10.0.0.100
- ARP responding to: who-has 10.0.0.100?
- ARP: updating 10.0.0.100 -> 02:50:2a:16:6d:02
- Iperf server: Received connection.
- Iperf client: Made connection to server.
- Iperf server: t = 1.000000, rate = 6307 KBits/s, totbytes = 788400, live_words = 119465
- Iperf server: t = 2.000000, rate = 32365 KBits/s, totbytes = 4834060, live_words = 121883
- Iperf server: t = 3.000000, rate = 30251 KBits/s, totbytes = 8615460, live_words = 124586
- Iperf server: t = 4.000000, rate = 29667 KBits/s, totbytes = 12323860, live_words = 87540
- Iperf server: t = 5.000000, rate = 31185 KBits/s, totbytes = 16222060, live_words = 74164
- Iperf server: t = 6.000000, rate = 31851 KBits/s, totbytes = 20203480, live_words = 84668
- ARP: timeout 10.0.0.101
- ARP: timeout 10.0.0.100
- ARP: timeout 10.0.0.101
- ARP: timeout 10.0.0.100
- ARP: timeout 10.0.0.101
- ARP: timeout 10.0.0.100
- test.byte: internal error, uncaught exception:
-            Sys_error("./_tests/iperf-0.output: No such file or directory")

[talex5]

Note: the new mirage-profile 0.5 has Counter.value and Counter.set_value, which may be useful if you want the option of graphing the stats over time, or correlating changes with other events.

[MagnusS]

@samoht Hm - do they also fail locally or only in travis?

[samoht]

The tests seem to pass fine locally.

[samoht]

Here are the iperf results. I'm not sure how to read the results ...

thomas@piana-5:~/git/mirage-tcpip$ ./test-debug.byte test iperf 0 -v
channel                                                                                                                                                                       [SKIP]
connect                                                                                                                                                                       [SKIP]
iperf    0   test_tcp_iperf_two_stacks_basic.               I am server with IP 10.0.0.100, expecting connections on port 5001
Manager: connect
Manager: configuring
Manager: Interface to 10.0.0.100 nm 255.255.255.0 gw [10.0.0.1]

ARP: sending gratuitous from 10.0.0.100
Manager: configuration done
I am client with IP 10.0.0.101, trying to connect to server @ 10.0.0.100:5001
Manager: connect
Manager: configuring
Manager: Interface to 10.0.0.101 nm 255.255.255.0 gw [10.0.0.1]

ARP: sending gratuitous from 10.0.0.101
ARP: updating 10.0.0.101 -> 02:50:2a:16:6d:03
Manager: configuration done
Iperf client: Attempting connection.
ARP: transmitting probe -> 10.0.0.100
ARP responding to: who-has 10.0.0.100?
ARP: updating 10.0.0.100 -> 02:50:2a:16:6d:02
Iperf server: Received connection.
Iperf client: Made connection to server.
Iperf server: t = 1.000000, rate = 56951 KBits/s, totbytes = 7118960, live_words = 66596
Iperf server: t = 2.000000, rate = 61495 KBits/s, totbytes = 14805860, live_words = 88565
Iperf server: t = 3.000000, rate = 61635 KBits/s, totbytes = 22510280, live_words = 89734
Iperf server: t = 3.000000, rate = 66666 KBits/s, totbytes = 25000000, live_words = 112557
Iperf client: Done.
Iperf server: Done - closed connection.
Waiting for server_done...
                                                                                                                    [OK]
iperf    1   test_tcp_iperf_two_stacks_trailing_bytes.                                                                                                                        [SKIP]
iperf    2   test_tcp_iperf_two_stacks_uniform_packet_loss.                                                                                                                   [SKIP]
Test Successful in 3.505s. 1 test run.

thomas@piana-5:~/git/mirage-tcpip$ ./test-master.byte test iperf 0 -v
channel                                                                                                                                                                       [SKIP]
connect                                                                                                                                                                       [SKIP]
iperf    0   test_tcp_iperf_two_stacks_basic.               I am server with IP 10.0.0.100, expecting connections on port 5001
Manager: connect
Manager: configuring
Manager: Interface to 10.0.0.100 nm 255.255.255.0 gw [10.0.0.1]

ARP: sending gratuitous from 10.0.0.100
Manager: configuration done
I am client with IP 10.0.0.101, trying to connect to server @ 10.0.0.100:5001
Manager: connect
Manager: configuring
Manager: Interface to 10.0.0.101 nm 255.255.255.0 gw [10.0.0.1]

ARP: sending gratuitous from 10.0.0.101
ARP: updating 10.0.0.101 -> 02:50:2a:16:6d:03
Manager: configuration done
Iperf client: Attempting connection.
ARP: transmitting probe -> 10.0.0.100
ARP responding to: who-has 10.0.0.100?
ARP: updating 10.0.0.100 -> 02:50:2a:16:6d:02
Iperf server: Received connection.
Iperf client: Made connection to server.
Iperf server: t = 1.000000, rate = 49126 KBits/s, totbytes = 6140760, live_words = 92402
Iperf server: t = 2.000000, rate = 71364 KBits/s, totbytes = 15061360, live_words = 127424
Iperf server: t = 3.000000, rate = 71773 KBits/s, totbytes = 24033060, live_words = 126719
Iperf server: t = 3.000000, rate = 66666 KBits/s, totbytes = 25000000, live_words = 126581
Iperf client: Done.
Iperf server: Done - closed connection.
Waiting for server_done...
                                                                                                                    [OK]
iperf    1   test_tcp_iperf_two_stacks_trailing_bytes.                                                                                                                        [SKIP]
iperf    2   test_tcp_iperf_two_stacks_uniform_packet_loss.                                                                                                                   [SKIP]
Test Successful in 3.047s. 1 test run.

[MagnusS]

You could increase the amount of data transferred to see if it stabilises (here). It's currently set to 25mb to not cause timeouts in Travis - but larger values should work fine locally.

[samoht]

An other option is to not run perf tests on travis (ie. make the tests Slow instead of Quick)

[MagnusS]

Yes, could do that if we can't get them to work reliably in Travis.

Any idea why it fails with this exception? Seems to be from the test framework, not the test

test.byte: internal error, uncaught exception:
-            Sys_error("./_tests/iperf-2.output: No such file or directory")

[samoht]

I've rebased on top of #149, let see if that makes Travis happy.

[samoht]

I've removed the debug calls from the hotpath (mainly Wire.xmit) There is a small performance cost in adding the debug code:

[with debug symbols, debug is disabled]
Iperf server: t = 1, rate = 43251d KBits/s, totbytes = 5406380, live_words = 89661
Iperf server: t = 2, rate = 74180d KBits/s, totbytes = 14678840, live_words = 120144
Iperf server: t = 3, rate = 76037d KBits/s, totbytes = 24183440, live_words = 111660
Iperf server: t = 4, rate = 77824d KBits/s, totbytes = 33911420, live_words = 87141
Iperf server: t = 5, rate = 78384d KBits/s, totbytes = 43709480, live_words = 74440
Iperf server: t = 6, rate = 77777d KBits/s, totbytes = 53431620, live_words = 113605
Iperf server: t = 7, rate = 77298d KBits/s, totbytes = 63093900, live_words = 106207

[without debug symbols]
Iperf server: t = 1, rate = 69134d KBits/s, totbytes = 8641740, live_words = 100759
Iperf server: t = 2, rate = 79004d KBits/s, totbytes = 18517180, live_words = 81729
Iperf server: t = 3, rate = 79915d KBits/s, totbytes = 28506500, live_words = 75873
Iperf server: t = 4, rate = 79074d KBits/s, totbytes = 38390700, live_words = 99391
Iperf server: t = 5, rate = 79307d KBits/s, totbytes = 48304100, live_words = 90748
Iperf server: t = 6, rate = 79319d KBits/s, totbytes = 58218960, live_words = 81020
Iperf server: t = 7, rate = 79950d KBits/s, totbytes = 68212660, live_words = 75310

I believe the gain in usability is worth the small performance hit, but I would welcome more feedback before merging (or not) this branch. @avsm @balrajsingh and all: what do you think?

[hannesm]

I appreciate debugging and think the speed loss is acceptable. 👍

[MagnusS]

I also think the speed loss is acceptable if it helps us debug the stack :-) The speed seems to vary a bit more with debug though. Does the pcap output from the test in tests/pcap look ok?

[balrajsingh]

I too think extra debug support is better.

Is it just a flag or setting that includes/excludes them, or is it more
complicated.
On 9 Jun 2015 10:31 pm, "Magnus Skjegstad" notifications@github.com wrote:

I also think the speed loss is acceptable if it helps us debug the stack
:-) The speed seems to vary a bit more with debug though. Does the pcap
output from the test in tests/pcap look ok?

—
Reply to this email directly or view it on GitHub
#142 (comment).

[samoht]

Basically every module can export some value of type Log.t, than you can decide to turn on at runtime using Tcp.Log.enable <the value>. For instance you can do in your application:

let () =
  Tcp.Log.enable Tcp.Pcb.debug ();
  Tcp.Log.enable Tcp.State.debug ()

to enable the debug statement of pcb.ml and state.ml on the console. You don't need to recompile the whole tcp/ip stack every time to comment/uncomment the statements you are interested in. I have some ideas to improve the performance of the debug statement when they are disabled (they still have a runtime cost currently, unfortunately), I'll try to do something tomorrow.

[MagnusS]

Hm - there seems to be something going on with the test that is commented out (iperf w/uniform packet loss). I just ran it 150+ times on the master branch locally without problems, but with the diff from this PR it times out regularly. I used the same data size (25mb).

Here's the pcap file from a test that timed out:
http://skjegstad.com/data/iperf_test_timeout.pcap