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 Thursday 17 July 2008, Christos Zoulas wrote:
> In article <200807171356.39961.sverre%viewmark.com@localhost>,
>
> Sverre Froyen  <sverre%viewmark.com@localhost> wrote:
> >Hi,
> >
> >I've changed the subject and I'm also copying pkgsrc-users.
> >
> >With i386 current (4.99.69) I am seing a dramatic slowdown in mysqld speed
> >whenever the server (actually my Thinkpad T42 laptop) is also running
> >compilations.  Here's an example:
> >
> >Inserting 65 records into a table normally takes 0.04s (real time).  If I
> > am doing a make in /usr/pkgsrc/shells/bash at the same time, it can take
> > more than 5s!
>
> Can you run "vmstat 1". 

The output looks normal.   Here's a sample:

 procs    memory      page                       disks   faults      cpu
 r b w    avm    fre  flt  re  pi   po   fr   sr w0 c0   in   sy  cs us sy id
 2 4 0 821372 967724 2583   0   0    0    0    0  2  0  393 2867 232 58 42  0
 3 4 0 819020 970080 2390   0   0    0    0    0  6  0  308 3093 183 56 44  0
 3 4 0 814668 974440 3248   0   0    0    0    0  4  0   92 2558 128 51 49  0

This is with LOCK_DEBUG so system time is running a little high.

> Are you swapping or paging?

No.  See above.  The computer has 2 GiB memory.

> how about a ktrace -t  
> A/ kdump -R?

Adding the -t A, adds a few lines of stop/resume kernel.  In the sample trace, 
below, there is an interesting delay which I have flagged as (this next delay 
is short if no load).  It appears to match the delay in unparking thread 2.  
I'm not sure how to interpret the "resume kernel" messages, however.

 27307      3 mysqld   0.000003911 read(0x14, 0xbb7a1000, 0x4) called
 27307      3 mysqld   0.000009219 stop kernel
 27307      3 mysqld   2.136315923 resume kernel
Idle delay since last insert (normal).
 27307      3 mysqld   0.000014528 read(0x14, 0xbb7a1000, 0x4) = 4
       ">\0\0\0"
 27307      3 mysqld   0.000010057 read(0x14, 0xbb7a1000, 0x3e) called
 27307      3 mysqld   0.000011734 read(0x14, 0xbb7a1000, 0x3e) = 62
       "\^Cinsert into ce_string values (0, 3, 'test', 0, 'aaa bbb ccc')"
 27307      3 mysqld   0.000005028 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40) 
called
 27307      3 mysqld   0.000005588 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40) 
= 0
 27307      3 mysqld   0.000005587 __sigprocmask14(0x3, 0xba3ffa40, 0) called
 27307      3 mysqld   0.000005029 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
 27307      3 mysqld   0.000005028 fcntl(0x14, 0x4, 0x6) called
 27307      3 mysqld   0.000004750 fcntl(0x14, 0x4, 0x6) = 0
 27307      3 mysqld   0.000006425 gettimeofday(0xba3ff40c, 0) called
 27307      3 mysqld   0.000004470 gettimeofday(0xba3ff40c, 0) = 0
 27307      3 mysqld   0.000010616 getpid() called
 27307      3 mysqld   0.000003632 getpid()        = 27307, 14621
 27307      3 mysqld   0.000003911 _sched_setparam(0x6aab, 0x3, 0, 0xba3ff3dc) 
called
 27307      3 mysqld   0.000010616 _sched_setparam(0x6aab, 0x3, 0, 0xba3ff3dc) 
= 0
 27307      3 mysqld   0.000092193 gettimeofday(0xba3fe72c, 0) called
 27307      3 mysqld   0.000005028 gettimeofday(0xba3fe72c, 0) = 0
 27307      3 mysqld   0.000234952 pwrite(0x16, 0xbb752014, 0x20, 0, 0x57228, 
0) called
 27307      3 mysqld   0.000056991 pwrite(0x16, 0xbb752014, 0x20, 0, 0x57228, 
0) = 32
       "\^C\0\^Z\^B\^D\M^V+\0\0\^C\0\0\0\^Dtest\vaaa bbb ccc\0\0"
 27307      3 mysqld   0.000009778 gettimeofday(0xba3fe79c, 0) called
 27307      3 mysqld   0.000004470 gettimeofday(0xba3fe79c, 0) = 0
 27307      3 mysqld   0.000010616 write(0x5, 0xbb759000, 0x98) called
 27307      3 mysqld   0.000042465 write(0x5, 0xbb759000, 0x98) = 152
       "\M-E\M-^\M^@H\^E\^A\0\0\0\^\\0\0\0\M-.\^A\0\0\0\0\^B\M^V+\0\0\0\0\0\0"
 27307      3 mysqld   0.000009778 pwrite(0x15, 0xba801000, 0x400, 0, 0x28400, 
0) called
 27307      3 mysqld   0.000027937 pwrite(0x15, 0xba801000, 0x400, 0, 0x28400, 
0) = 1024
       "\^C\^Y\0\0\0\0\^C\^Dtest\0\0\0\0\0\0\0\^EP\b\^R(\^RH\^Rh\^R\M^H\^R"
 27307      3 mysqld   0.000004470 pwrite(0x15, 0xba800800, 0x400, 0, 0x28800, 
0) called
 27307      3 mysqld   0.000025143 pwrite(0x15, 0xba800800, 0x400, 0, 0x28800, 
0) = 1024
       "\^A\M^R\0\0+o\0\0\0\^EmH\0\0+p\0\0\0\^Emh\0\0+q\0\0\0\^Em\M^H\0\0+r\0"
 27307      3 mysqld   0.000005867 pwrite(0x15, 0xba3fd450, 0x94, 0, 0, 0) 
called
 27307      3 mysqld   0.000027099 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"
 27307      3 mysqld   0.000007822 write(0x14, 0xbb7a1000, 0xd) called
 27307      3 mysqld   0.000011454 write(0x14, 0xbb7a1000, 0xd) = 13
       "\t\0\0\^A\0\^A\M-|\M^V+\^B\0\0\0"
 27307      3 mysqld   0.000009778 getpid() called
 27307      3 mysqld   0.000005308 getpid()        = 27307, 14621
 27307      3 mysqld   0.000003912 _sched_setparam(0x6aab, 0x3, 0, 0xba3ff3dc) 
called
 27307      3 mysqld   0.000007822 _sched_setparam(0x6aab, 0x3, 0, 0xba3ff3dc) 
Err#1 EPERM
 27307      3 mysqld   0.000006984 gettimeofday(0xba3ff3dc, 0) called
 27307      3 mysqld   0.000004470 gettimeofday(0xba3ff3dc, 0) = 0
 27307      3 mysqld   0.000005308 read(0x14, 0xbb7a1000, 0x4) called
 27307      3 mysqld   0.000005308 read(0x14, 0xbb7a1000, 0x4) Err#35 EAGAIN
 27307      3 mysqld   0.000003912 gettimeofday(0xba3ffa0c, 0) called
 27307      3 mysqld   0.000005028 gettimeofday(0xba3ffa0c, 0) = 0
 27307      3 mysqld   0.000003912 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40) 
called
 27307      3 mysqld   0.000004749 __sigprocmask14(0x1, 0x84e71d0, 0xba3ffa40) 
= 0
 27307      3 mysqld   0.000005587 _lwp_kill(0x2, 0xe) called
 27307      3 mysqld   0.000011175 _lwp_kill(0x2, 0xe) = 0
 27307      2 mysqld   -3.862885634 stop kernel
Idle delay since last insert (normal).
 27307      2 mysqld   2.137128055 resume kernel
 27307      2 mysqld   0.000008661 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0) = 
0
 27307      2 mysqld   0.000005867 __sigprocmask14(0x3, 0x84e71d0, 0xba5ffd30) 
called
 27307      2 mysqld   0.000005028 __sigprocmask14(0x3, 0x84e71d0, 0xba5ffd30) 
= 0
 27307      2 mysqld   0.000004749 _lwp_park(0, 0, 0x84e71b0, 0x84e71b0) 
called
 27307      3 mysqld   1.077899490 _lwp_unpark(0x2, 0x84e71b0) called
 27307      3 mysqld   0.000010896 _lwp_unpark(0x2, 0x84e71b0) = 0
 27307      2 mysqld   -2.922096878 stop kernel
******* This next delay is short if no load.
 27307      2 mysqld   1.077914856 resume kernel
 27307      2 mysqld   0.000003631 _lwp_park(0, 0, 0x84e71b0, 0x84e71b0) = 0
 27307      2 mysqld   0.000006146 gettimeofday(0xba5ffcdc, 0) called
 27307      2 mysqld   0.000005029 gettimeofday(0xba5ffcdc, 0) = 0
 27307      2 mysqld   0.000005308 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) called
 27307      2 mysqld   0.000010058 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) = 0
 27307      2 mysqld   0.000004469 __sigprocmask14(0x3, 0xba5ffd30, 0) called
 27307      2 mysqld   0.000005588 __sigprocmask14(0x3, 0xba5ffd30, 0) = 0
 27307      2 mysqld   0.000007822 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0) 
called
 27307      3 mysqld   0.000014807 __sigprocmask14(0x3, 0xba3ffa40, 0) called
 27307      3 mysqld   0.000005308 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
 27307      3 mysqld   0.000005867 fcntl(0x14, 0x4, 0x2) called
 27307      3 mysqld   0.000005308 fcntl(0x14, 0x4, 0x2) = 0
 27307      3 mysqld   0.000005867 read(0x14, 0xbb7a1000, 0x4) called

> Have you tried http://www.netbsd.org/~ad/pdaemon.diff

I have and it makes no difference.  I also tried the M2 scheduler.  Again no 
discernible difference.

Ideas?

Thanks,
Sverre



Home | Main Index | Thread Index | Old Index