https://bugs.dragonflybsd.org/https://bugs.dragonflybsd.org/favicon.ico?16293952082006-06-21T13:35:10ZDragonFlyBSD bugtrackerDragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33852006-06-21T13:35:10Zcorecode
<ul></ul><p>Okay, joerg and me could speed pkgsrc building up a bit by telling pkgsrc to use the builtin for test and [.</p>
<p>However, look at this:</p>
<p>avg fork parent: 0.000148<br />avg fork child: 0.004091</p>
<p>(rough rough numbers, will be off if there are multiple processes running concurrently)</p>
<p>5ms seems to be a good estimate for fork performance. but mind you, that's the child which is taking longer. This means the parent returns <strong>first</strong>, then starts wait4'ing (usually, or blocks on a read or so), then some time passes and then <strong>later</strong> the child returns from fork. Seems wrong to me.</p>
<p>so much statistics for now, cheers<br /> simon</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33862006-06-21T13:35:10Zcorecode
<ul></ul><p>Okay, less rough numbers:</p>
<p>122991 104/s fork</p>
<p>avg fork parent: 0.000157<br />avg fork child: 0.002563</p>
<p>so if we assume that the parent always waits for the child, it'll take 0.267 seconds per second (in average) to fork? That means 1/4 of the time is just spent until the child start running.</p>
<p>the above numbers include vfork, these are without:</p>
<p>avg fork parent: 0.000144<br />avg fork child: 0.002556</p>
<p>same, basically. Maybe teaching sh(1) to use vfork could give some performance improvement?</p>
<p>cheers<br /> simon</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33882006-06-21T13:35:10Zdillon
<ul></ul><p>:Okay, less rough numbers:<br />:<br />:122991 104/s fork<br />:<br />:avg fork parent: 0.000157<br />:avg fork child: 0.002563<br />:<br />:so if we assume that the parent always waits for the child, it'll take 0.267 seconds per second (in average) to fork? That means 1/4 of the time is just spent until the child start running.<br />:<br />:the above numbers include vfork, these are without:<br />:<br />:avg fork parent: 0.000144<br />:avg fork child: 0.002556<br />:<br />:same, basically. Maybe teaching sh(1) to use vfork could give some performance improvement?<br />:<br />:cheers<br />: simon</p>
<pre><code>There is always something running somewhere when you fork. Either the<br /> child is running or the parent is running. Either way both have to run<br /> to their completion before the next program can be execed when running<br /> a shell script since the script serializes everything.</code></pre>
<pre><code>It tends to be more efficient to allow the parent to continue to run<br /> (that is, to return from the fork) because there are fewer context<br /> switches.</code></pre>
<pre><code>parent child<br /> ---------- -----------<br /> fork() -<br /> wait -<br /> - run<br /> - run<br /> - run<br /> - run<br /> - exit<br /> waitreturn</code></pre>
<pre><code>parent child<br /> ---------- -----------<br /> fork() -<br /> - run<br /> - run<br /> - run<br /> wait - <<< 2 extra context switches<br /> - run<br /> - run<br /> - exit<br /> waitreturn</code></pre>
<pre><code>I would rather not try to optimize programs to use vfork(). There<br /> just isn't a whole lot of difference between fork and vfork.</code></pre>
<pre><code>Most of the time spent by the child is not waiting for the parent<br /> to switch it in, but instead is being spent in execl(). It may be<br /> possible to speed up execution by making certain dynamic binaries <br /> resident (with the 'resident' command). Everything in /bin is<br /> statically linked alredy, though, and already execs as fast as it is<br /> possible to exec a program. But perhaps pkgsrc is using certain<br /> binaries internally that are dynamically linked. I suggest taking<br /> a good look at what pkgsrc runs.</code></pre>
<pre><code>There is a fork test program in /usr/src/test/sysperf/fork1.c.<br /> (make /tmp/fork1 from /usr/src/test/sysperf). I get around <br /> 154 uS for a complete fork/exit/wait sequence on my test box.<br /> A time of 2 mS indicates that something else is going on.. either<br /> other processes are running or whatever you are execing is taking<br /> a long time to initialize (which would not be surprising if we are<br /> talking about /bin/sh here).</code></pre>
<pre><code>The GNU configure script crap is just that... crap. In a typical<br /> pkgsrc build that script will probably be run thousands of times,<br /> doing the same tests with slow shell scripts over and over and over<br /> and over and over and over again. It's really the stupidest gnu thing<br /> I've ever seen in my life. It was stupid a decade ago, and its still<br /> stupid today.</code></pre>
<pre><code>-Matt</code></pre> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33902006-06-21T13:35:10Zcorecode
<ul></ul><p>No, my point was that the child takes some time to even return from the fork, despite the parent already wait()ing. There is some gap involved where the system seemingly just schedules somebody else instead or so.</p>
<p>Ah, I see the point. This however does not explain why the child takes some time to be scheduled.</p>
<p>I think our vfork is not completely optimized. We could for instance make vfork not COW the vmspace, because the user is only allowed to call _exit and exec(). I don't think we are doing this right now.</p>
<p>That's actually not true:</p>
<p>Total runtime 1171.642231 sec</p>
<p>122991 104/s 0.002616 321.756458 fork_child<br />122991 104/s 0.000148 18.181783 fork_parent<br />112576 96/s 0.000235 26.489667 execve<br />239985 204/s 0.000080 19.174908 open<br />(etc)</p>
<p>total exec time is not very high.</p>
<p>I'm not talking about fork/exec performance. This is from a build kdump, taking the CALL and RET times and calculating the duration of the syscall.</p>
<p>cheers<br /> simon</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33912006-06-21T13:35:10Zdillon
<ul></ul><p>Those numbers don't make any sense. What program are you using to<br /> try to measure the child fork return time ?</p>
<pre><code>-Matt</code></pre> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33922006-06-21T13:35:10Zcorecode
<ul></ul><p>ktrace. These are real numbers, not a microbenchmark. There might be a little bit of load interfering, dunno. You can grab the dump from <<a class="external" href="http://chlamydia.fs.ei.tum.de/~corecode/unsorted/kdump.out.bz2">http://chlamydia.fs.ei.tum.de/~corecode/unsorted/kdump.out.bz2</a>></p>
<p>cheers<br /> simon</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33942006-06-21T13:35:10Zdillon
<ul></ul><p>:ktrace. These are real numbers, not a microbenchmark. There might be a little bit of load interfering, dunno. You can grab the dump from <<a class="external" href="http://chlamydia.fs.ei.tum.de/~corecode/unsorted/kdump.out.bz2">http://chlamydia.fs.ei.tum.de/~corecode/unsorted/kdump.out.bz2</a>><br />:<br />:cheers<br />: simon</p>
<pre><code>Use kdump -R !!!</code></pre>
<pre><code>In anycase, it does look odd. But I can't reproduce the effect<br /> when I ktrace a similar bmake from pkgsrc and there are cases <br /> in your dump where you don't get large timeouts:</code></pre>
<p>66255 sh 1185522939.738309 CALL fork<br />66255 sh 1185522939.738419 RET fork 66264/0x102d8<br />66255 sh 1185522939.738665 CALL getpgrp<br />66255 sh 1185522939.738676 RET getpgrp 5268/0x1494<br />66255 sh 1185522939.738730 CALL wait4(0xffffffff,0xbfbff318,0x2,0)<br />66264 sh 1185522939.738745 RET fork 0<br /> <----------- 15 uS (326 uS from original<br /> fork)<br />66264 sh 1185522939.739292 CALL open(0x280de1c8,0x601,0x1b6)<br />66264 sh 1185522939.739306 NAMI "/dev/null" <br />66264 sh 1185522939.739346 RET open 5</p>
<pre><code>What it looks like is happening is that there are other processes<br /> running that get the cpu after the fork/wait4, before the child<br /> gets the cpu. Insofar as I can tell it looks like there is a cpu-bound<br /> program running that is simply not making any system calls to be traced,<br /> or is not being traced.</code></pre>
<pre><code>Are you running anything in parallel during this test or running<br /> a parallel build of some sort?</code></pre>
<pre><code>-Matt</code></pre> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33952006-06-21T13:35:10Zcorecode
<ul></ul><p>heh. well, the absolute ones help me process the time automatically.</p>
<p>Yah, quite possible. However, why'd that only happen for for fork and not for other possibly blocking syscalls (or vfork)? I think we need some better, performance-counter based tracing tools, rather than plain kdump output.</p>
<p>I don't remember anymore, probably there was a build going on in parallel. But again, I'm not trying to benchmark, I'm trying to find a cause for the slow build speed.</p>
<p>cheers<br /> simon</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=33962006-06-21T13:35:10Zdillon
<ul></ul><p>:Yah, quite possible. However, why'd that only happen for for fork and not for other possibly blocking syscalls (or vfork)? I think we need some better, performance-counter based tracing tools, rather than plain kdump output.</p>
<pre><code>There really isn't a whole lot of difference between fork and vfork,<br /> but I noticed at the end of your dump that both fork and vfork had<br /> much shorter delays then what I saw at the beginning of your dump.</code></pre>
<p>:> Are you running anything in parallel during this test or running<br />:> a parallel build of some sort?<br />:<br />:I don't remember anymore, probably there was a build going on in parallel. But again, I'm not trying to benchmark, I'm trying to find a cause for the slow build speed.<br />:<br />:cheers<br />: simon</p>
<pre><code>Its called a script titled 'gnu configure'. Do a systat -vm 1 and look<br /> at the name cache hit stats. Everything bmake, gcc, and especially the<br /> gnu configure script do is extremely filesystem intensive. And in the<br /> case of gnu configure, also mostly redundant.</code></pre>
<pre><code>-Matt</code></pre> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=34002006-06-21T13:35:10Zjoerg
<ul></ul><p>When NetBSD implemented a real vfork back around NetBSD 1.4 or so, it<br />made difference in the percent range for a full buildworld. Basically,<br />you can avoid the duplication of the VM space <strong>and</strong> the COW faulting,<br />which sums up.</p>
<p>While a lot of bad things can be said about autoconf, it was the only<br />usable, semi-generic solution for over a decade. There is still only<br /><strong>one</strong> good alternative (and that is using C++...). The biggest complain<br />most maintainers on non-default (from the upstream POV) platform had in<br />all that time was that it is hard to use correctly. E.g. many tests can<br />be done a lot more intelligently than most configure scripts do. Given<br />that autoconf follows the "stand-alone" paradigm (as opposed to imake<br />for some parts of the problem domain), it actually implements it quite<br />well.</p>
<p>Joerg</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=113362006-06-21T13:35:10Ztuxillo
<ul><li><strong>Description</strong> updated (<a title="View differences" href="/journals/11336/diff?detail_id=852">diff</a>)</li><li><strong>Status</strong> changed from <i>New</i> to <i>In Progress</i></li><li><strong>Assignee</strong> deleted (<del><i>0</i></del>)</li></ul><p>Hi all,</p>
<p>I've not seen that much intr% time during bulk builds, at least when I did some a couple months ago.<br />ftigeot/marino/dillon, can you please confirm this doesn't happen during poudriere builds now?</p>
<p>Thanks,<br />Antonio Huete</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=117912006-06-21T13:35:10Ztuxillo
<ul><li><strong>Description</strong> updated (<a title="View differences" href="/journals/11791/diff?detail_id=1421">diff</a>)</li><li><strong>Category</strong> set to <i>Other</i></li><li><strong>Assignee</strong> set to <i>tuxillo</i></li><li><strong>Target version</strong> set to <i>3.8</i></li></ul><p>Grab.</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=119952006-06-21T13:35:10Ztuxillo
<ul><li><strong>Category</strong> changed from <i>Other</i> to <i>Unverifiable</i></li><li><strong>Status</strong> changed from <i>In Progress</i> to <i>Feedback</i></li><li><strong>Target version</strong> changed from <i>3.8</i> to <i>Unverifiable</i></li></ul><p>Hi,</p>
<p>Moving to Unverifiable because:<br />- Many VM related work done to x64 at least.<br />- vfork/exec work was done by Matt in the end of 2013.<br />- We don't do pkgsrc bulkbuilds anymore but we do poudriere builds which are very fork-heavy and as far as I know this issue hasn't showed up.</p>
<p>Feel free to resurrect/provide feedback.</p>
<p>Cheers,<br />Antonio Huete</p> DragonFlyBSD - Bug #745: the evil interrupt stats monster is still around!https://bugs.dragonflybsd.org/issues/745?journal_id=143922022-06-25T11:05:15Ztuxillo
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Closed</i></li><li><strong>Target version</strong> changed from <i>Unverifiable</i> to <i>6.4</i></li></ul><p>Over a decade marked as Unverifiable.</p>