<div dir="ltr"><div><div>Sorry about the truncated log - the full one is gzipped here: <a href="http://www.charliebelmer.com/scallion.log.gz" target="_blank">http://www.charliebelmer.com/scallion.log.gz</a><br><br></div>I'll do some Chutney testing - I saw what looked like a good tutorial on this list earlier this month so let me give it a shot.<br>
<br></div><div>Thanks!<br></div><div><br></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Sep 10, 2013 at 6:17 AM, Karsten Loesing <span dir="ltr"><<a href="mailto:karsten@torproject.org" target="_blank">karsten@torproject.org</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="im">On 9/7/13 5:57 PM, Charlie Belmer wrote:<br>
> Hey Karsten & Dev team,<br>
><br>
> I didn't mean to take this off channel, so my apologies for that.<br>
><br>
> I ran a few more tests this week (and my apologies on the slowness of some<br>
> of this work - life has been hectic this past month), but I am not finding<br>
> much of use. I could not find any errors which are not also present in when<br>
> N23 is disabled. If you want to browse the logs for yourself, I uploaded a<br>
> partial log from a run to <a href="http://www.charliebelmer.com/scallion.n23.log(730MB)" target="_blank">http://www.charliebelmer.com/scallion.n23.log(730MB)</a>.<br>
<br>
</div>That log ends at simulated time 0:19:34, so 5:30 minutes before the<br>
actual requests start.  Can you post both full logs somewhere, maybe<br>
gzipped to save bandwidth?<br>
<div class="im"><br>
> The most telling entries I found so far are below, but I see the same<br>
> errors whether UseN23 is set to 1 or not, so it is likely not the root<br>
> cause. I'll keep digging.<br>
<br>
</div>Okay.<br>
<br>
Another option would be to run your branch in Chutney to find the bug<br>
and then return to Shadow for performance measurements.  That's what I<br>
did with #9166 and it helped a lot.  Let me know if you need help with that.<br>
<br>
Thanks!<br>
<span class="HOEnZb"><font color="#888888">Karsten<br>
</font></span><div class="HOEnZb"><div class="h5"><br>
<br>
> Error 1 (Seems to occur when opening channel):<br>
> 0:0:49:406270 [thread-2] 0:9:41:348157618 [scallion-info]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] bw_weights_error_t<br>
> networkstatus_check_weights(int64_t, int64_t, int64_t, int64_t, int64_t,<br>
> int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t,<br>
> int64_t, int)(): Bw weight mismatch 1. G=214 M=12174 E=165 D=27654 T=40207<br>
> Wmd=4769 Wme=-724848 Wmg=0 Wed=461 Wee=734848 Wgd=4769 Wgg=10000<br>
> Wme=-724848 Wmg=0<br>
> 0:0:49:407692 [thread-2] 0:9:41:348157618 [scallion-info]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] bw_weights_error_t<br>
> networkstatus_check_weights(int64_t, int64_t, int64_t, int64_t, int64_t,<br>
> int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t,<br>
> int64_t, int)(): Bw weight mismatch 1. G=214 M=12174 E=165 D=27654 T=40207<br>
> Wmd=4769 Wme=-724848 Wmg=0 Wed=461 Wee=734848 Wgd=4769 Wgg=10000<br>
> Wme=-724848 Wmg=0<br>
><br>
> Error 2:<br>
> 0:0:54:227263 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void conn_read_callback(int,<br>
> short, void *)(): socket 1000264 wants to read.<br>
> 0:0:54:227281 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int<br>
> connection_read_to_buf(connection_t *, ssize_t *, int *)(): 1000264:<br>
> starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.<br>
> 0:0:54:227302 [thread-2] 0:10:55:012000001 [shadow-debug]<br>
> [4uthority1-73.1.0.0] [_tcp_endOfFileSignalled] <a href="http://73.1.0.0:10021" target="_blank">73.1.0.0:10021</a> (descriptor<br>
> 1000264) <-> <a href="http://91.1.0.0:9111" target="_blank">91.1.0.0:9111</a>: signaling close to user, socket no longer usable<br>
> 0:0:54:227321 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] TLS error: unexpected close<br>
> while reading (SSL negotiation finished successfully)<br>
> 0:0:54:227338 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int tor_tls_read(tor_tls_t *,<br>
> char *, size_t)(): read returned r=0, err=-8<br>
> 0:0:54:227354 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int<br>
> connection_read_to_buf(connection_t *, ssize_t *, int *)(): TLS connection<br>
> closed on read. Closing. (Nickname nonexit10, address 91.1.0.0)<br>
> 0:0:54:227373 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> channel_close_for_error(channel_t *)(): Closing channel 0x7f546d03ce40 due<br>
> to lower-layer error<br>
> 0:0:54:227389 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> channel_change_state(channel_t *, channel_state_t)(): Changing state of<br>
> channel 0x7f546d03ce40 (global ID 21) from "open" to "closing"<br>
> 0:0:54:227420 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> channel_remove_from_digest_map(channel_t *)(): Removed channel<br>
> 0x7f546d03ce40 (global ID 21) from identity map in state closing (4) with<br>
> digest BBF25A366EA5376B0026CE6EDE3DF536211429BE<br>
> 0:0:54:227440 [thread-2] 0:10:55:012000001 [shadow-debug]<br>
> [4uthority1-73.1.0.0] [tcp_close] <a href="http://73.1.0.0:10021" target="_blank">73.1.0.0:10021</a> (descriptor 1000264) <-><br>
> <a href="http://91.1.0.0:9111" target="_blank">91.1.0.0:9111</a>:  user closed connection<br>
> 0:0:54:227452 [thread-2] 0:10:55:012000001 [shadow-debug]<br>
> [4uthority1-73.1.0.0] [_tcp_setState] <a href="http://73.1.0.0:10021" target="_blank">73.1.0.0:10021</a> (descriptor 1000264)<br>
> <-> <a href="http://91.1.0.0:9111" target="_blank">91.1.0.0:9111</a>: moved from TCP state 'TCPS_CLOSEWAIT' to 'TCPS_LASTACK'<br>
> 0:0:54:227473 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> connection_mark_for_close_internal_(connection_t *, int, const char *)():<br>
> Calling connection_mark_for_close_internal_() on an OR conn at<br>
> /home/coffee/shadow/shadow/build/tor/src/or/connection.c:2932<br>
> 0:0:54:227491 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int<br>
> conn_close_if_marked(int)(): Cleaning up connection (fd -1).<br>
> 0:0:54:227509 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> circuit_n_chan_done(channel_t *, int)(): chan to NULL/<a href="http://91.1.0.0:9111" target="_blank">91.1.0.0:9111</a>,<br>
> status=0<br>
> 0:0:54:227546 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void<br>
> channel_change_state(channel_t *, channel_state_t)(): Changing state of<br>
> channel 0x7f546d03ce40 (global ID 21) from "closing" to "channel error"<br>
> 0:0:54:227565 [thread-2] 0:10:55:012000001 [scallion-debug]<br>
> [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int<br>
> connection_remove(connection_t *)(): removing socket -1 (type OR), n_conns<br>
> now 26<br>
><br>
><br>
><br>
><br>
> On Tue, Sep 3, 2013 at 10:47 AM, Karsten Loesing <<a href="mailto:karsten@torproject.org">karsten@torproject.org</a>>wrote:<br>
><br>
>> On 9/3/13 4:32 PM, Charlie Belmer wrote:<br>
>>> Hi Karsten,<br>
>>><br>
>>> I have run several tests, but I haven't been able to satisfy myself yet.<br>
>> I<br>
>>> attached the results from my latest round of tests for your review. I am<br>
>>> comparing the n23 branch (UseN23 1 set in each torrc) with the initial<br>
>> head<br>
>>> I merged n23 with. It seems that for some reason, the n23 branch<br>
>> completes<br>
>>> far fewer downloads, though I haven't yet found the cause, or found<br>
>>> anything interesting in the logs.<br>
>>><br>
>>> $ grep "fg-download-complete" m1.large-tor/data/scallion.log | wc -l<br>
>>> 8827<br>
>>> $ grep "fg-download-complete" m1.large-n23/scallion.log | wc -l<br>
>>> 308<br>
>>><br>
>>> I would definitely appreciate any thoughts, insights, or advice!<br>
>><br>
>> Interesting!  Can you re-run the n23 simulation on info or even debug<br>
>> log level?  That might reveal some more information.  You'll do that by<br>
>> running "scallion --log-level=INFO".  A tiny network should be<br>
>> sufficient for that.  Watch out for filling disks.<br>
>><br>
>> If you want me to look at the scallion.log file, feel free to post it<br>
>> somewhere, and I'll see if something looks unusual to me.<br>
>><br>
>> Thanks,<br>
>> Karsten<br>
>><br>
>><br>
>>> On Tue, Sep 3, 2013 at 8:58 AM, Karsten Loesing <<a href="mailto:karsten@torproject.org">karsten@torproject.org</a><br>
>>> wrote:<br>
>>><br>
>>>> Hi Charlie,<br>
>>>><br>
>>>> did you have the chance to simulate your rebased n23-5 branch using<br>
>> Shadow?<br>
>>>><br>
>>>> If not, maybe I can help by simulating it once and writing down more<br>
>>>> specific instructions for you?<br>
>>>><br>
>>>> Thanks!<br>
>>>> Karsten<br>
>>>><br>
>>>><br>
>>>> On 8/8/13 10:36 AM, Karsten Loesing wrote:<br>
>>>>> (Moving this discussion back to tor-dev@ with Charlie's permission.)<br>
>>>>><br>
>>>>> On 8/6/13 4:10 AM, Charlie Belmer wrote:<br>
>>>>>> Hey Karsten,<br>
>>>>>><br>
>>>>>> I've been reading up on Shadow & Scallion to do some performance<br>
>>>> testing on<br>
>>>>>> N23. Before I go too far down that road, I wanted to check in with<br>
>> you.<br>
>>>>>><br>
>>>>>> Are there existing blueprints or best practices I should be following?<br>
>>>>><br>
>>>>> Thanks for looking into this!<br>
>>>>><br>
>>>>> So, I wouldn't call the following notes blueprints or best practices,<br>
>>>>> but they are a description of what I would do to run Shadow simulations<br>
>>>>> of your branch.<br>
>>>>><br>
>>>>> First of all, be sure to read the Shadow wiki which has contains lots<br>
>> of<br>
>>>>> interesting stuff: <a href="https://github.com/shadow/shadow/wiki" target="_blank">https://github.com/shadow/shadow/wiki</a><br>
>>>>><br>
>>>>> The next step would be to get a vanilla Tor master (that your branch is<br>
>>>>> based on) running in a minimal or tiny Shadow network.  It's probably<br>
>>>>> easiest to use a local Ubuntu VM for this.  Or you can start an<br>
>> m1.large<br>
>>>>> EC2 instance for the tiny network, or an even smaller instance for the<br>
>>>>> minimal network.<br>
>>>>><br>
>>>>> Once that simulation succeeds, you'll want to run another simulation<br>
>>>>> using your branch, extract performance metrics using Shadow's analyze<br>
>>>>> script, produce a PDF with graphs also using the analyze script, and<br>
>>>>> then wonder if things are faster than before.<br>
>>>>><br>
>>>>> The minimal or tiny networks are mostly there to learn that things are<br>
>>>>> working as expected.  You'll probably want larger networks for real<br>
>>>>> performance results, but starting small to get everything working is<br>
>>>>> probably easier.<br>
>>>>><br>
>>>>> Sounds doable, I guess.  However, here's where things start to get<br>
>>>>> tricky: in order to simulate Tor master (or a branch based on it) in<br>
>>>>> Shadow, you'll have to perform quite a few extra steps like compiling<br>
>>>>> your own CMake and Clang/LLVM.  Not really hard, but you need to get<br>
>> all<br>
>>>>> pieces together before Shadow does what you want.<br>
>>>>><br>
>>>>> I'm pasting detailed instructions that I used to simulate Steven's uTP<br>
>>>>> branch in Shadow below as an example.  Not everything applies to your<br>
>>>>> branch, but it should give you the general idea.<br>
>>>>><br>
>>>>> If something remains unclear, please feel free to ask!<br>
>>>>><br>
>>>>>> Depending how it goes, I'd also look at re-trying adaptive 23 or<br>
>> tuning<br>
>>>> the<br>
>>>>>> existing implementation.<br>
>>>>><br>
>>>>> Neat!  We should probably include Mashael in that discussion once you<br>
>>>>> have a working and simulated n23-5 branch.  Maybe she has ideas what<br>
>>>>> parts need tweaking.  I'm cc'ing her in this mail so she knows what<br>
>>>>> you're working on.<br>
>>>>><br>
>>>>> In any case, having a working rebased n23-5 branch is already a big<br>
>> step<br>
>>>>> forward.<br>
>>>>><br>
>>>>> Thanks!<br>
>>>>> Karsten<br>
>>>>><br>
>>>>><br>
>>>>> === START OF INSTRUCTIONS ===<br>
>>>>><br>
>>>>> Launch new EC2 instance running Ubuntu Server 13.04 64 bit<br>
>>>>><br>
>>>>> Set ulimit -n to 25000, see Shadow wiki for details<br>
>>>>><br>
>>>><br>
>> <a href="https://github.com/shadow/shadow/wiki/Preparing-your-machine#system-configs-and-limits" target="_blank">https://github.com/shadow/shadow/wiki/Preparing-your-machine#system-configs-and-limits</a><br>
>>>>><br>
>>>>> $ sudo apt-get update<br>
>>>>> $ sudo apt-get upgrade<br>
>>>>><br>
>>>>> Clone and test-compile modified libutp<br>
>>>>><br>
>>>>> $ sudo apt-get install build-essential git automake libssl-dev<br>
>>>> libevent-dev<br>
>>>>> $ mkdir src<br>
>>>>> $ cd src/<br>
>>>>> $ git clone <a href="https://github.com/sjmurdoch/libutp" target="_blank">https://github.com/sjmurdoch/libutp</a><br>
>>>>> $ cd libutp/<br>
>>>>> $ make<br>
>>>>> $ cd ../<br>
>>>>><br>
>>>>> Clone and test-compile Tor branch utp<br>
>>>>><br>
>>>>> $ git clone <a href="https://git.torproject.org/tor.git" target="_blank">https://git.torproject.org/tor.git</a><br>
>>>>> $ cd tor/<br>
>>>>> $ git remote add sjm217 <a href="https://git.torproject.org/sjm217/tor.git" target="_blank">https://git.torproject.org/sjm217/tor.git</a><br>
>>>>> $ git fetch sjm217<br>
>>>>> $ git checkout -b utp sjm217/utp<br>
>>>>> $ ./autogen.sh<br>
>>>>> $ LDFLAGS="-L/home/ubuntu/src/libutp"<br>
>> CFLAGS="-I/home/ubuntu/src/libutp"<br>
>>>>> LIBS="-lutp -lrt" ./configure --disable-asciidoc<br>
>>>>> $ make<br>
>>>>> $ make distclean<br>
>>>>> $ cd ../<br>
>>>>><br>
>>>>> Modify Tor to use uTP for all links (or "0 &&" for not using uTP for<br>
>> any<br>
>>>>> link)<br>
>>>>><br>
>>>>> diff --git a/src/or/channeltls.c b/src/or/channeltls.c<br>
>>>>> index 0551b73..b7b36e1 100644<br>
>>>>> --- a/src/or/channeltls.c<br>
>>>>> +++ b/src/or/channeltls.c<br>
>>>>> @@ -418,7 +418,7 @@ channel_tls_connect(const tor_addr_t *addr,<br>
>> uint16_t<br>
>>>>> port,<br>
>>>>>    /* Create a uTP connection */<br>
>>>>>    tor_addr_to_sockaddr(addr, port, (struct sockaddr*)&sin,<br>
>> sizeof(sin));<br>
>>>>>    tor_addr_to_str(addr_str, addr, sizeof(addr_str), 0);<br>
>>>>> -  if (!strncmp(addr_str, "128.232.10.129", sizeof(addr_str))) {<br>
>>>>> +  if (1 || !strncmp(addr_str, "128.232.10.129", sizeof(addr_str))) {<br>
>>>>>      log_info(LD_CHANNEL,<br>
>>>>>               "Trying uTP connection to %s", addr_str);<br>
>>>>>      tlschan->utp = UTP_Create(tor_UTPSendToProc, tlschan, (const<br>
>> struct<br>
>>>>> sockaddr*)&sin,<br>
>>>>><br>
>>>>> Install CMake 2.8.10<br>
>>>>><br>
>>>>> $ wget <a href="http://www.cmake.org/files/v2.8/cmake-2.8.10.2.tar.gz" target="_blank">http://www.cmake.org/files/v2.8/cmake-2.8.10.2.tar.gz</a><br>
>>>>> $ tar xf cmake-2.8.10.2.tar.gz<br>
>>>>> $ cd cmake-2.8.10.2/<br>
>>>>> $ ./configure<br>
>>>>> $ make<br>
>>>>> $ export PATH=~/src/cmake-2.8.10.2/bin:$PATH<br>
>>>>> $ cd ../<br>
>>>>> $ which cmake # result: /home/ubuntu/src/cmake-2.8.10.2/bin/cmake<br>
>>>>><br>
>>>>> Build Clang and LLVM from source<br>
>>>>><br>
>>>>> $ wget <a href="http://llvm.org/releases/3.2/llvm-3.2.src.tar.gz" target="_blank">http://llvm.org/releases/3.2/llvm-3.2.src.tar.gz</a><br>
>>>>> $ wget <a href="http://llvm.org/releases/3.2/clang-3.2.src.tar.gz" target="_blank">http://llvm.org/releases/3.2/clang-3.2.src.tar.gz</a><br>
>>>>> $ tar xaf llvm-3.2.src.tar.gz<br>
>>>>> $ tar xaf clang-3.2.src.tar.gz<br>
>>>>> $ cp -R clang-3.2.src llvm-3.2.src/tools/clang<br>
>>>>> $ cd llvm-3.2.src/<br>
>>>>> $ mkdir build<br>
>>>>> $ cd build/<br>
>>>>> $ cmake -DCMAKE_INSTALL_PREFIX=/home/ubuntu/.local ../.<br>
>>>>> $ make<br>
>>>>> $ make install<br>
>>>>> $ export PATH=~/.local/bin/:$PATH<br>
>>>>> $ cd ../../<br>
>>>>> $ which clang # result: /home/ubuntu/.local/bin//clang<br>
>>>>><br>
>>>>> Install Shadow<br>
>>>>><br>
>>>>> $ sudo apt-get install gcc xz-utils make automake autoconf cmake tidy<br>
>>>>> libtidy-dev libglib2.0 libglib2.0-dev dstat pdftk python2.7<br>
>>>>> python-matplotlib python-numpy python-scipy<br>
>>>>> $ git clone <a href="https://github.com/shadow/shadow.git" target="_blank">https://github.com/shadow/shadow.git</a><br>
>>>>> $ cd shadow<br>
>>>>> $ ./setup dependencies<br>
>>>>> $ ./setup build -g -i /home/ubuntu/src/libutp -i<br>
>>>>> /usr/include/x86_64-linux-gnu/c++/4.7 -l /home/ubuntu/src/libutp<br>
>>>>> --tor-prefix /home/ubuntu/src/tor --tor-lib utp<br>
>>>>> $ ./setup install<br>
>>>>> $ export PATH=~/.shadow/bin/:$PATH<br>
>>>>><br>
>>>>> Simulate tiny network in Shadow<br>
>>>>><br>
>>>>> $ cd resource/examples/scallion/<br>
>>>>> $ tar xf tiny-4GB-m1.large.tar.xz<br>
>>>>> $ cd tiny-4GB-m1.large/<br>
>>>>> $ scallion<br>
>>>>><br>
>>>>> Graph simulation results<br>
>>>>><br>
>>>>> Add one line to beginning of analyze.py:<br>
>>>>><br>
>>>>> import matplotlib; matplotlib.use('Agg')<br>
>>>>><br>
>>>>> For additional traffic simulations:<br>
>>>>><br>
>>>>> $ grep -v "\[traffic-" scallion.log > scallion-notraffic.log<br>
>>>>><br>
>>>>> $ cd ~/src/<br>
>>>>> $ mkdir results<br>
>>>>> $ cd results/<br>
>>>>> $ python ~/src/shadow/contrib/analyze.py parse --output uTP-1<br>
>>>>><br>
>>>><br>
>> ~/src/shadow/resource/examples/scallion/tiny-4GB-m1.large/data-utp-1/scallion.log<br>
>>>>> $ python ~/src/shadow/contrib/analyze.py parse --output uTP-0<br>
>>>>><br>
>>>><br>
>> ~/src/shadow/resource/examples/scallion/tiny-4GB-m1.large/data-utp-0/scallion.log<br>
>>>>> $ python ~/src/shadow/contrib/analyze.py parse --output vanilla<br>
>>>>><br>
>>>><br>
>> ~/src/shadow/resource/examples/scallion/tiny-4GB-m1.large/data-vanilla/scallion.log<br>
>>>>> $ python ~/src/shadow/contrib/analyze.py plot --title "sjm217's utp<br>
>>>>> branch (#9166)" --prefix "sjm217-utp" --data vanilla/ "vanilla<br>
>>>>> 0.2.4.4-alpha" --data uTP-1/ "uTP for all links" --data uTP-0/ "uTP for<br>
>>>>> none of the links"<br>
>>>>><br>
>>>>> === END OF INSTRUCTIONS ===<br>
>>>>><br>
>>>>><br>
>>>><br>
>>>><br>
>>><br>
>><br>
>><br>
><br>
<br>
</div></div></blockquote></div><br></div>