|
From: Nicholas N. <n.n...@gm...> - 2009-04-23 03:10:32
|
Hi, Some time in the last few days, on my ubuntu box, helgrind/tests/tc19_shadowmem started running incredibly slowly under DRD. It used to take a few seconds, now it takes about 5 minutes. It happens with both 32-bit and 64-bit builds. It's still fast under Helgrind. The weird thing is that it doesn't appear due to a change in Valgrind. No recent changes seem like they could possibly have caused this, and the slow-down occurred even with some old (eg. not updated for weeks or months) Valgrind versions I had lying around (eg. r9419, which is over a month old). tc19_shadowmem.c hasn't changed since November 2008. I'm wondering if a software update on my machine could have caused it, but I can't even work out how to determine what software was update recently. Any other thoughts? It's pretty annoying because it makes the regtests difficult to run. Nick |
|
From: Nicholas N. <n.n...@gm...> - 2009-04-23 03:52:39
|
On Thu, Apr 23, 2009 at 1:10 PM, Nicholas Nethercote
<n.n...@gm...> wrote:
> Hi,
>
> Some time in the last few days, on my ubuntu box,
> helgrind/tests/tc19_shadowmem started running incredibly slowly under
> DRD. It used to take a few seconds, now it takes about 5 minutes. It
> happens with both 32-bit and 64-bit builds. It's still fast under
> Helgrind.
>
> Any other thoughts? It's pretty annoying because it makes the
> regtests difficult to run.
Doing some more investigation:
- the pthread_join() calls are slow
- they cause DRD_(thread_post_join) to be called
- within it, DRD_(finish_supression) is the slow part
- within it, DRD_(bm_clear_store) is the slow part
The DRD_(finish_suppression) call looks like this:
DRD_(finish_suppression)(DRD_(thread_get_stack_max)(drd_joinee)
- DRD_(thread_get_stack_size)(drd_joinee),
DRD_(thread_get_stack_max)(drd_joinee));
Those two arguments are exactly 8MB apart.
So it looks like the thread stacks are 8MB, which seems rather large
-- I thought the main stack was typically something like that size,
but that thread stacks were much smaller, maybe 64KB or something?
If I use ulimit to change the stack size to 512KB, it only takes about
13 seconds to run. If I change the stack size to 64KB, it only takes
about 2.7 seconds to run.
Could the thread stack size on my machine have changed spontaneously somehow?
Nick
|
|
From: Julian S. <js...@ac...> - 2009-04-23 07:28:11
|
> So it looks like the thread stacks are 8MB, which seems rather large > -- I thought the main stack was typically something like that size, > but that thread stacks were much smaller, maybe 64KB or something? I thought the thread stacks are 2M, but really am not sure. > Could the thread stack size on my machine have changed spontaneously > somehow? Sounds unlikely, unless your glibc got majorly updated somehow? But that too sounds unlikely. J |
|
From: Michael S. <ms...@xi...> - 2009-04-23 17:14:50
|
On Wed, Apr 22, 2009 at 8:52 PM, Nicholas Nethercote <n.n...@gm...> wrote: > So it looks like the thread stacks are 8MB, which seems rather large > -- I thought the main stack was typically something like that size, > but that thread stacks were much smaller, maybe 64KB or something? Thread stacks on linux default to 8MB. Which is absurdly large, but that's ok. I wouldn't think it likely that that would have changed system-wide - it's been the default for many years. Mike |
|
From: Bart V. A. <bar...@gm...> - 2009-04-23 19:50:06
|
On Thu, Apr 23, 2009 at 5:10 AM, Nicholas Nethercote <n.n...@gm...> wrote: > Some time in the last few days, on my ubuntu box, > helgrind/tests/tc19_shadowmem started running incredibly slowly under > DRD. It used to take a few seconds, now it takes about 5 minutes. It > happens with both 32-bit and 64-bit builds. It's still fast under > Helgrind. You are not doing justice to DRD with such comments. Anyone who looks at user comments or at the bug database can see that since the time DRD is no longer an experimental tool it is doing a great job. The performance of the DRD tool is acceptable: for some programs it runs slightly faster than Helgrind and for some other it runs slightly slower. The program tc19_shadowmem is an exception for which DRD runs significantly slower than Helgrind. Your e-mail creates the impression that at some time there would have been a change in DRD that caused it to process tc19_shadowmem a lot slower than before. This is not correct. About a month ago (March 10, 2009) you informed me via private e-mail that there was an error in the file drd/tests/tc19_shadowmem.vgtest which caused this test to be skipped by DRD. This error was fixed on the same day (r9337) and since then during the regression tests DRD runs the program tc19_shadowmem. After having read your e-mail I started looking at why DRD was processing tc19_shadowmem so slowly. By this time DRD should process this test program significantly faster -- on my PC it is now processed in 50s. Bart. |
|
From: Nicholas N. <n.n...@gm...> - 2009-04-24 01:54:00
|
On Fri, Apr 24, 2009 at 5:49 AM, Bart Van Assche <bar...@gm...> wrote: > On Thu, Apr 23, 2009 at 5:10 AM, Nicholas Nethercote > <n.n...@gm...> wrote: >> Some time in the last few days, on my ubuntu box, >> helgrind/tests/tc19_shadowmem started running incredibly slowly under >> DRD. It used to take a few seconds, now it takes about 5 minutes. It >> happens with both 32-bit and 64-bit builds. It's still fast under >> Helgrind. > > You are not doing justice to DRD with such comments. Anyone who looks > at user comments or at the bug database can see that since the time > DRD is no longer an experimental tool it is doing a great job. The > performance of the DRD tool is acceptable: for some programs it runs > slightly faster than Helgrind and for some other it runs slightly > slower. The program tc19_shadowmem is an exception for which DRD runs > significantly slower than Helgrind. > > Your e-mail creates the impression that at some time there would have > been a change in DRD that caused it to process tc19_shadowmem a lot > slower than before. This is not correct. About a month ago (March 10, > 2009) you informed me via private e-mail that there was an error in > the file drd/tests/tc19_shadowmem.vgtest which caused this test to be > skipped by DRD. This error was fixed on the same day (r9337) and since > then during the regression tests DRD runs the program tc19_shadowmem. I wasn't aiming to criticise DRD, I was aiming to understand some mysterious behaviour on my machine. I made this clear in my original email: "The weird thing is that it doesn't appear due to a change in Valgrind. No recent changes seem like they could possibly have caused this... I'm wondering if a software update on my machine could have caused it" Moving on, I did some further investigating, and found some very strange behaviour: - If I run 'make regtest', it takes 6:08 minutes - If I run '/usr/bin/perl tests/vg_regtest memcheck cachegrind callgrind massif lackey none helgrind drd exp-omega exp-ptrcheck', it takes 11:07 minutes. This command is exactly what is run by 'make regtest', after it runs the 'check' target. I then tried removing drd/tests/tc19_shadowtest: - 'make regtest' takes 5:03 minutes - '/usr/inb/perl tests/vg_regtest ...' takes 6:23 minutes So the conclusion is that running the regtests via "make check" somehow makes drd/tests/tc19_shadowmem *much* faster (ie. 1 minute instead of 5), and also makes all the other tests a little bit faster (ie. 1 minute faster for the rest of the regtests). It's all repeatable, too. This makes no sense to me at all. So I guess nothing has changed, either in DRD or on my system; tc19_shadowmem probably always did take almost 5 minutes by itself, but probably I only ever ran it under "make regtest" before now, never by itself. > After having read your e-mail I started looking at why DRD was > processing tc19_shadowmem so slowly. By this time DRD should process > this test program significantly faster -- on my PC it is now processed > in 50s. After updating, I get these results: - drd/tests/tc19_shadowmem by itself takes 17s - 'make regtest' takes 4:51 minutes - '/usr/inb/perl tests/vg_regtest ...' takes 5:08 minutes 5 minutes to 17 seconds is a big improvement! Thanks for looking into it. The difference between the 'make regtest' time and the 'perl tests/vg_regtest ...' time is much smaller too, which is good for my sanity. Nick |
|
From: Robert O'C. <ro...@oc...> - 2009-04-25 00:55:07
|
You might want to check the alignment of the stack pointer. We had some weird issues with Tracemonkey performance varying based on how you spawned the test, which turned out to be due to the stack pointer getting different initial values in different runs. Rob -- "He was pierced for our transgressions, he was crushed for our iniquities; the punishment that brought us peace was upon him, and by his wounds we are healed. We all, like sheep, have gone astray, each of us has turned to his own way; and the LORD has laid on him the iniquity of us all." [Isaiah 53:5-6] |
|
From: Bart V. A. <bar...@gm...> - 2009-04-25 15:25:39
|
On Fri, Apr 24, 2009 at 3:30 AM, Nicholas Nethercote <n.n...@gm...> wrote: > After updating, I get these results: > > - drd/tests/tc19_shadowmem by itself takes 17s > - 'make regtest' takes 4:51 minutes > - '/usr/inb/perl tests/vg_regtest ...' takes 5:08 minutes > > 5 minutes to 17 seconds is a big improvement! Thanks for looking into it. Update: after another optimization the command "time perl tests/vg_regtest drd/tests/tc19_shadowmem" now completes in about three seconds (trunk revision 9629). Performance of DRD for other programs is now improved too, but only a few percent. As I already wrote, the tc19_shadowmem test program is an exception. Bart. |