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