https://redmine.named-data.net/https://redmine.named-data.net/favicon.ico?14759811232016-04-28T12:49:05ZNDN project issue tracking systemNFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=155872016-04-28T12:49:05ZJunxiao Shi
<ul><li><strong>Blocked by</strong> <i><a class="issue tracker-2 status-5 priority-2 priority-default closed" href="/issues/3571">Feature #3571</a>: FIB+PIT benchmark</i> added</li></ul> NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=155912016-04-28T23:44:04ZZhuo Lizhuoli@email.arizona.edu
<ul><li><strong>Start date</strong> set to <i>04/29/2016</i></li></ul> NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=160032016-07-07T15:35:44ZZhuo Lizhuoli@email.arizona.edu
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>In Progress</i></li></ul> NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=162402016-07-22T11:15:06ZJunxiao Shi
<ul><li><strong>Status</strong> changed from <i>In Progress</i> to <i>New</i></li><li><strong>Assignee</strong> deleted (<del><i>Zhuo Li</i></del>)</li><li><strong>Start date</strong> deleted (<del><i>04/29/2016</i></del>)</li></ul><p>Beichuan says Zhuo will not work on this recently.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=162582016-07-23T03:02:18ZJunxiao Shi
<ul><li><strong>Assignee</strong> set to <i>Chengyu Fan</i></li></ul><p>Chengyu agrees to work on this issue but he cannot start until August.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168392016-08-29T14:52:27ZChengyu Fanchengyu@cs.colostate.edu
<ul><li><strong>File</strong> <a href="/attachments/658">callgrind.pit-fib-performance-profiling.out</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/658/callgrind.pit-fib-performance-profiling.out">callgrind.pit-fib-performance-profiling.out</a> added</li><li><strong>% Done</strong> changed from <i>0</i> to <i>100</i></li></ul><p>I have run the pit_fib performance test on an ONL Host8core machine. The Callgrind profiling output file is uploaded. Please use kcachegrind to open it for details.</p>
<p>The pit-fib-benchmark.cpp simulates FIB and PIT operations on one million Interest-Data exchanges. It generates packets and populates FIB before the actual tests. The tests include finding longest prefix match in FIB, finding matched Data in PIT and erasing PIT entries.</p>
<p>The results show that the FIB and PIT tests take 11374372 microseconds. The whole pit-fib-benchmark takes 25.655s. This means more than half of the time is used by the generatePacketsAndPopulateFib() function. FIB and PIT operations (exclude generatePacketsAndPopulateFib()) can achieve 87,950 Interest-Data exchanges per second.</p>
<p>More information is given below:</p>
<pre><code>
(1) generatePacketsAndPopulateFib() takes 49.15% of the running time.
Its child, the ndn::Name::Name constructor uses around 26.06%. The other child nfd::fib::insert() takes 8.74%
(2) Pit as a whole takes 44.46%
nfd::Pit::findOrInsert() takes 19.92%
nfd::Pit::findAllDataMatches() takes 16.37%
nfd::Pit::erase() uses the other 8.32%
(3) the most time-consuming ndn function is ndn::Name::wireEncode() 21.51%.
It is called by both nfd::name_tree::computeHash() 14.00% and nfd::name_tree::computeHashSet() 7.52%
(4) NameTree:
a. the most time-consuming NameTree function is nfd::NameTree::lookup() 26.01%.
The Fib::insert() contributes 8.74% (called by generatePacketsAndPopulateFib()). The rest is from Pit::findOrInsert() 19.92%.
b. another time-consuming function is nfd::NameTree::findAllMatches() 12.90%. They are from nfd::Pit::findAllDataMatches()
</code></pre>
<p>Since the ndn::Name::wireEncode() alone uses 21.51% of time, I have tried to use TCMalloc library to optimize the memory management. The results confirmed my assumption. The FIB and PIT operations go down to 8499654 microseconds. This means FIB and PIT operations can achieve 117,647 Interest-Data exchanges per second.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168422016-08-29T16:02:08ZJunxiao Shi
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Feedback</i></li></ul><p>I should have said this earlier, but <code>generatePacketsAndPopulateFib</code> should not be part of the profiling: it's the initial setup.<br><br>
Can you report only the portion between two <code>time::steady_clock::now()</code> calls?<br><br>
<a href="https://github.com/named-data/NFD/blob/dbef6dc8e2e32160b9e826ca0f32b9a00bb759df/tests/other/pit-fib-benchmark.cpp#L118-L133">https://github.com/named-data/NFD/blob/dbef6dc8e2e32160b9e826ca0f32b9a00bb759df/tests/other/pit-fib-benchmark.cpp#L118-L133</a></p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168432016-08-29T16:25:04ZDavide Pesavento
<ul></ul><p>Please provide the exact versions of NFD and ndn-cxx (git commit SHA) used to perform the test in note-6.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168442016-08-29T16:41:51ZChengyu Fanchengyu@cs.colostate.edu
<ul></ul><p>The number I reported is the time between two time::steady_clock::now() calls.</p>
<p>Since I have trouble to install openssl library for ndn-cxx on ONL, I used the older version. The ndn-cxx is 0.4.1 (commit SHA = 2e52d7cab4e03631db7f6c89a2daf7de590dd29e). The NFD is 4f1afaca16ba02b40651f62e0f28e56d0b7cbf9f, which is the commit for face system benchmark, but I modified the pit-fib-benchmark.cpp code as <a href="https://gerrit.named-data.net/#/c/3021/">https://gerrit.named-data.net/#/c/3021/</a>.</p>
<p>Please let me know if I chose the wrong version.</p>
<p>Without TCMalloc, the time between two time::steady_clock::now() calls is 11374372 microseconds. With TCMalloc, the time is 8499654 microseconds.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168452016-08-29T17:05:55ZJunxiao Shi
<ul></ul><p>It's necessary to rerun the profiling with latest version, because I have changed <code>NameTree</code> significantly.<br><br>
The profiling should only report function calls between two <code>now</code>s; it should exclude anything under initial setup procedure.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168512016-08-30T14:20:12ZChengyu Fanchengyu@cs.colostate.edu
<ul><li><strong>File</strong> <a href="/attachments/661">callgrind.pit-fib-performance-profiling.out</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/661/callgrind.pit-fib-performance-profiling.out">callgrind.pit-fib-performance-profiling.out</a> added</li><li><strong>File</strong> <a href="/attachments/662">call-graph-for-pit-fib-operations.png</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/662/call-graph-for-pit-fib-operations.png">call-graph-for-pit-fib-operations.png</a> added</li></ul><p>The profiling results for the latest NFD (9685cc5682c9e1d642747649294f469e316733ab) is uploaded. The ndn-cxx version used for this test is 667370f102f7953968a6d0d60a782cf0ef33d9d5. The profiling is running for the portion between two time::steady_clock::now() calls. Please refer to the uploaded file call-graph-for-pit-fib-operations.png for the call graph.</p>
<pre><code>(1) nfd::Pit::findOrInsert() takes 42.33% of the running time
(2) nfd::Pit::findAllDataMatches() takes 39.51%
(3) nfd::Pit::erase() uses the other 16.23%
(4) ndn::Name::wireEncode() uses 40.27%, and it is called by nfd::name_tree::computesHash()
</code></pre>
<p>To measure the time between two time::steady_clock::now() calls, I run 10 experiments for both without TCMalloc and with TCMalloc. <br>
Without TCMalloc, the time is in range (7833889, 10918891) microseconds, and the median is 8606859.5 microseconds. With TCMalloc, the time is in range (6012537, 8827668) microseconds, and the median is 6935110.5 microseconds.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168532016-08-30T18:23:14ZDavide Pesavento
<ul></ul><p>Chengyu Fan wrote:</p>
<blockquote>
<p>The profiling is running for the portion between two time::steady_clock::now() calls.</p>
</blockquote>
<p>How did you do that? Did you put <code>CALLGRIND_{START,STOP}_INSTRUMENTATION</code> macros in the code?</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168542016-08-30T19:29:48ZChengyu Fanchengyu@cs.colostate.edu
<ul></ul><p>Davide Pesavento wrote:</p>
<blockquote>
<p>Chengyu Fan wrote:</p>
<blockquote>
<p>The profiling is running for the portion between two time::steady_clock::now() calls.</p>
</blockquote>
<p>How did you do that? Did you put <code>CALLGRIND_{START,STOP}_INSTRUMENTATION</code> macros in the code?</p>
</blockquote>
<p>Yes, I added these macros in the pit-fib-benchmark.cpp code. Please let me know if there are any issues</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168562016-08-31T00:49:55ZDavide Pesavento
<ul></ul><p>That's good, it's what I had in mind. We should probably add those calls to the committed benchmark code for posterity's sake. I'll prepare a patch.</p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168722016-08-31T20:09:07ZDavide Pesavento
<ul></ul><p><a href="https://gerrit.named-data.net/3155">https://gerrit.named-data.net/3155</a></p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=168732016-09-01T00:48:53ZDavide Pesavento
<ul></ul><p>Junxiao asks on gerrit:</p>
<blockquote>
<p>Can you post on Redmine the command line to generate a callgrind report? I need to test this.</p>
</blockquote>
<p><code>$ valgrind --tool=callgrind --instr-atstart=no ./build/whatever</code></p>
NFD - Task #3610: FIB+PIT profilinghttps://redmine.named-data.net/issues/3610?journal_id=220222018-01-25T13:11:12ZDavide Pesavento
<ul><li><strong>Category</strong> deleted (<del><i>Integration Tests</i></del>)</li><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Closed</i></li></ul>