Current-Users archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
Re: Dramatic mysqld slowness when running compiles in parallel
On Friday 18 July 2008, Joerg Sonnenberger wrote:
> On Fri, Jul 18, 2008 at 03:05:14PM -0600, Sverre Froyen wrote:
> > This is with LOCK_DEBUG so system time is running a little high.
>
> [snip]
>
> > Ideas?
>
> Just to make sure: do you see this behaviour without LOCK_DEBUG as well?
I do but it is less severe. I might have to run two kernel compiles in
parallel in order to see the same length delays with a GENERIC kernel that I
see running a single compilation with a LOCK_DEBUG kernel.
The following trace was done with a GENERIC kernel and with a single kernel
compilation running. The delay before the lwp_unpark call is only 0.21s in
this case.
I'm guessing that the resume kernel delay for thread 2 is really just a
consequence of the thread 3 delay before its call to lwp_unpark and, as such,
a red herring.
6242 3 mysqld 0.000001955 read(0x14, 0xbb7a1000, 0x4) called
6242 3 mysqld 0.000002515 stop kernel
6242 3 mysqld 354.672049890 resume kernel
6242 3 mysqld 0.000010896 read(0x14, 0xbb7a1000, 0x4) = 4
">\0\0\0"
6242 3 mysqld 0.000011454 read(0x14, 0xbb7a1000, 0x3e) called
6242 3 mysqld 0.000009219 read(0x14, 0xbb7a1000, 0x3e) = 62
"\^Cinsert into ce_string values (0, 3, 'test', 0, 'aaa bbb ccc')"
6242 3 mysqld 0.000004191 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40)
called
6242 3 mysqld 0.000002793 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40)
= 0
6242 3 mysqld 0.000004470 __sigprocmask14(0x3, 0xba3ffa40, 0) called
6242 3 mysqld 0.000002515 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
6242 3 mysqld 0.000004470 fcntl(0x14, 0x4, 0x6) called
6242 3 mysqld 0.000003911 fcntl(0x14, 0x4, 0x6) = 0
6242 3 mysqld 0.000006146 gettimeofday(0xba3ff40c, 0) called
6242 3 mysqld 0.000003911 gettimeofday(0xba3ff40c, 0) = 0
6242 3 mysqld 0.000013131 getpid() called
6242 3 mysqld 0.000002514 getpid() = 6242, 13736
6242 3 mysqld 0.000003353 _sched_setparam(0x1862, 0x3, 0, 0xba3ff3dc)
called
6242 3 mysqld 0.000007822 _sched_setparam(0x1862, 0x3, 0, 0xba3ff3dc)
= 0
6242 3 mysqld 0.000124320 gettimeofday(0xba3fe72c, 0) called
6242 3 mysqld 0.000003632 gettimeofday(0xba3fe72c, 0) = 0
6242 3 mysqld 0.000085767 pwrite(0x16, 0xbb719414, 0x20, 0, 0x288, 0)
called
6242 3 mysqld 0.000050567 pwrite(0x16, 0xbb719414, 0x20, 0, 0x288, 0)
= 32
"\^C\0\^Z\^B\^D-\0\0\0\^C\0\0\0\^Dtest\vaaa bbb ccc\0\0"
6242 3 mysqld 0.000011174 gettimeofday(0xba3fe79c, 0) called
6242 3 mysqld 0.000003353 gettimeofday(0xba3fe79c, 0) = 0
6242 3 mysqld 0.000012851 write(0x5, 0xbb759000, 0x98) called
6242 3 mysqld 0.000028217 write(0x5, 0xbb759000, 0x98) = 152
"\M-0\^N\M^AH\^E\^A\0\0\0\^\\0\0\0\M-^\^B\0\0\0\0\^B-\0\0\0\0\0\0\0"
6242 3 mysqld 0.000012851 pwrite(0x15, 0xba800000, 0x400, 0, 0x400,
0) called
6242 3 mysqld 0.000043861 pwrite(0x15, 0xba800000, 0x400, 0, 0x400,
0) = 1024
"\0\M-|\0\0\0\^U\0\0\0\0\0\0\0\0\0\^V\0\0\0\0\0\^X\0\0\0\^W\0\0\0\0"
6242 3 mysqld 0.000004750 pwrite(0x15, 0xba800400, 0x400, 0, 0x800,
0) called
6242 3 mysqld 0.000015086 pwrite(0x15, 0xba800400, 0x400, 0, 0x800,
0) = 1024
"\^A\^N\0\0\0\0\^C\^Dtest\0\0\0\0\0\0\0\0\^B\b\^R(\^RH\^Rh\^R\M^H\^C\v"
6242 3 mysqld 0.000006704 pwrite(0x15, 0xba3fd450, 0x94, 0, 0, 0)
called
6242 3 mysqld 0.000011455 pwrite(0x15, 0xba3fd450, 0x94, 0, 0, 0) =
148
"\M-~\M-~\a\^A\0\^C\^A\M-?\0\M-0\0d\0\M-X\0\^D\0\0\^B\0!\^A\0\0\0\^A9"
6242 3 mysqld 0.000008940 write(0x14, 0xbb7a1000, 0xb) called
6242 3 mysqld 0.000008381 write(0x14, 0xbb7a1000, 0xb) = 11
"\a\0\0\^A\0\^A-\^B\0\0\0"
6242 3 mysqld 0.000010895 getpid() called
6242 3 mysqld 0.000002235 getpid() = 6242, 13736
6242 3 mysqld 0.000003353 _sched_setparam(0x1862, 0x3, 0, 0xba3ff3dc)
called
6242 3 mysqld 0.000004190 _sched_setparam(0x1862, 0x3, 0, 0xba3ff3dc)
Err#1 EPERM
6242 3 mysqld 0.000007823 gettimeofday(0xba3ff3dc, 0) called
6242 3 mysqld 0.000003632 gettimeofday(0xba3ff3dc, 0) = 0
6242 3 mysqld 0.000005308 read(0x14, 0xbb7a1000, 0x4) called
6242 3 mysqld 0.000003911 read(0x14, 0xbb7a1000, 0x4) Err#35 EAGAIN
6242 3 mysqld 0.000003352 gettimeofday(0xba3ffa0c, 0) called
6242 3 mysqld 0.000004191 gettimeofday(0xba3ffa0c, 0) = 0
6242 3 mysqld 0.000003352 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40)
called
6242 3 mysqld 0.000002235 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40)
= 0
6242 3 mysqld 0.000005029 _lwp_kill(0x2, 0xe) called
6242 3 mysqld 0.000007264 _lwp_kill(0x2, 0xe) = 0
6242 2 mysqld -355.327346387 stop kernel
6242 2 mysqld 354.672662273 resume kernel
6242 2 mysqld 0.000005308 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0) =
0
6242 2 mysqld 0.000005308 __sigprocmask14(0x3, 0x84e71d0, 0xba5ffd30)
called
6242 2 mysqld 0.000002794 __sigprocmask14(0x3, 0x84e71d0, 0xba5ffd30)
= 0
6242 2 mysqld 0.000004470 _lwp_park(0, 0, 0x84e71b0, 0x84e71b0)
called
6242 3 mysqld 0.215164923 _lwp_unpark(0x2, 0x84e71b0) called
6242 3 mysqld 0.000006985 _lwp_unpark(0x2, 0x84e71b0) = 0
6242 2 mysqld -1.784831724 stop kernel
6242 2 mysqld 0.215177216 resume kernel
6242 2 mysqld 0.000002793 _lwp_park(0, 0, 0x84e71b0, 0x84e71b0) = 0
6242 2 mysqld 0.000005308 gettimeofday(0xba5ffcdc, 0) called
6242 2 mysqld 0.000004191 gettimeofday(0xba5ffcdc, 0) = 0
6242 2 mysqld 0.000005029 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) called
6242 2 mysqld 0.000008101 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) = 0
6242 2 mysqld 0.000003632 __sigprocmask14(0x3, 0xba5ffd30, 0) called
6242 2 mysqld 0.000003632 __sigprocmask14(0x3, 0xba5ffd30, 0) = 0
6242 2 mysqld 0.000006426 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0)
called
6242 3 mysqld 0.000010895 __sigprocmask14(0x3, 0xba3ffa40, 0) called
6242 3 mysqld 0.000002794 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
6242 3 mysqld 0.000005029 fcntl(0x14, 0x4, 0x2) called
6242 3 mysqld 0.000004749 fcntl(0x14, 0x4, 0x2) = 0
6242 3 mysqld 0.000005029 read(0x14, 0xbb7a1000, 0x4) called
Sverre
Home |
Main Index |
Thread Index |
Old Index