Current-Users archive

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]

Dramatic mysqld slowness when running compiles in parallel



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!

The inserted records are small:

insert into ce_string values (0, 3, 'test', 0, 'aaa bbb ccc');

and the table structure is unremarkable:

CREATE TABLE `ce_string` (
  `CE_STRING_ID` int(11) NOT NULL auto_increment,
  `CONTENT_ID` int(11) NOT NULL,
  `KEY_PREFIX` varchar(31) NOT NULL,
  `CINDEX` int(11) NOT NULL default '0',
  `STRING` varchar(255) NOT NULL default '',
  PRIMARY KEY  (`CE_STRING_ID`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8

NetBSD 4.0 on the same computer does not exhibit the same slowdown.

Using ktruss -R on mysqld, I get the following trace for a single insert:

  7035      3 mysqld   0.000003632 read(0x14, 0xbb7a1000, 0x4) called
  7035      3 mysqld   0.000008940 read(0x14, 0xbb7a1000, 0x4) = 4
       ">\0\0\0"
  7035      3 mysqld   0.000003352 read(0x14, 0xbb7a1000, 0x3e) called
  7035      3 mysqld   0.000006985 read(0x14, 0xbb7a1000, 0x3e) = 62
       "\^Cinsert into ce_string values (0, 3, 'test', 0, 'aaa bbb ccc')"
  7035      3 mysqld   0.000001955 __sigprocmask14(0x1, 0x84e6f30, 0xba3ffa40) 
called
  7035      3 mysqld   0.000001676 __sigprocmask14(0x1, 0x84e6f30, 0xba3ffa40) 
= 0
  7035      3 mysqld   0.000002515 __sigprocmask14(0x3, 0xba3ffa40, 0) called
  7035      3 mysqld   0.000001955 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
  7035      3 mysqld   0.000001677 fcntl(0x14, 0x4, 0x6) called
  7035      3 mysqld   0.000001676 fcntl(0x14, 0x4, 0x6) = 0
  7035      3 mysqld   0.000003632 gettimeofday(0xba3ff40c, 0) called
  7035      3 mysqld   0.000002235 gettimeofday(0xba3ff40c, 0) = 0
  7035      3 mysqld   0.000008660 getpid() called
  7035      3 mysqld   0.000001676 getpid()        = 7035, 8080
  7035      3 mysqld   0.000039671 _sched_setparam(0x1b7b, 0x3, 0, 0xba3ff3dc) 
called
  7035      3 mysqld   0.000004749 _sched_setparam(0x1b7b, 0x3, 0, 0xba3ff3dc) 
= 0
  7035      3 mysqld   0.000092751 gettimeofday(0xba3fe72c, 0) called
  7035      3 mysqld   0.000003353 gettimeofday(0xba3fe72c, 0) = 0
  7035      3 mysqld   0.000174607 pwrite(0x16, 0xbb719814, 0x20, 0, 0x5668, 
0) called
  7035      3 mysqld   0.000014527 pwrite(0x16, 0xbb719814, 0x20, 0, 0x5668, 
0) = 32
       "\^C\0\^Z\^B\^D\M-T\^D\0\0\^C\0\0\0\^Dtest\vaaa bbb ccc\0\0"
  7035      3 mysqld   0.000007822 gettimeofday(0xba3fe79c, 0) called
  7035      3 mysqld   0.000002235 gettimeofday(0xba3fe79c, 0) = 0
  7035      3 mysqld   0.000009220 write(0x5, 0xbb759000, 0x98) called
  7035      3 mysqld   0.000011454 write(0x5, 0xbb759000, 0x98) = 152
       
"\M-E\M-Y{H\^E\^A\0\0\0\^\\0\0\0\M^V\n\0\0\0\0\^B\M-T\^D\0\0\0\0\0\0\M-E\M-Y{H\^B\^A\0\0\0|
\0\0\0\^R\v\0\0\0\0\^A\0\0\0\0\0\0\0\^D\0\0\^Z\0\0\0@\0\0\^A\0\0\0\0\0\0\0\0\^F\^Cstd\^D!
\0!\0"
  7035      3 mysqld   0.000007543 pwrite(0x15, 0xba800c00, 0x400, 0, 0x2c00, 
0) called
  7035      3 mysqld   0.000021511 pwrite(0x15, 0xba800c00, 0x400, 0, 0x2c00, 
0) = 1024
       
"\^B\M-G\0\0\0\0\^C\^Dtest\0\0\0\0\0\0\0\0<\b\^R(\^RH\^Rh\^R\M^H\^R\M-(\^R\M-H\^R\M-h\^Q=\b\^R(\^RH\^Rh\^R\M^H\^R\M-(\^R\M-H\^R\M-h\^Q>\b\^R(\^RH\^Rh\^R\M^H\^R\M-(\^R\M-H\^R\M-h\^Q?
\b"
  7035      3 mysqld   0.000002515 pwrite(0x15, 0xba800400, 0x400, 0, 0x3000, 
0) called
  7035      3 mysqld   0.000007822 pwrite(0x15, 0xba800400, 0x400, 0, 0x3000, 
0) = 1024
       
"\^CJ\0\0\^D\M^A\0\0\0\0L\b\0\0\^D\M^B\0\0\0\0L(\0\0\^D\M^C\0\0\0\0LH\0\0\^D\M^D\0\0\0\0Lh\0\0\^D\M^E\0\0\0\0L\M^H\0\0\^D\M^F\0\0\0\0L\M-(\0\0\^D\M^G\0\0\0\0L\M-H\0\0\^D\M^H\0\0\0\0L"
  7035      3 mysqld   0.000004749 pwrite(0x15, 0xba3fd450, 0x94, 0, 0, 0) 
called
  7035      3 mysqld   0.000006705 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\M^?\0\0\0\0\0\0\^B\M-8\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^B\M-8\M^?
\M^?\M^?\M^?\M^?\M^?\M^?\M^?\0\0\0\0\0\0004\0\0\0\0\0"
  7035      3 mysqld   0.000006147 write(0x14, 0xbb7a1000, 0xd) called
  7035      3 mysqld   0.000009219 write(0x14, 0xbb7a1000, 0xd) = 13
       "\t\0\0\^A\0\^A\M-|\M-T\^D\^B\0\0\0"
  7035      3 mysqld   0.220735991 getpid() called
  7035      3 mysqld   0.000003352 getpid()        = 7035, 8080
  7035      3 mysqld   0.000002514 _sched_setparam(0x1b7b, 0x3, 0, 0xba3ff3dc) 
called
  7035      3 mysqld   0.000005588 _sched_setparam(0x1b7b, 0x3, 0, 0xba3ff3dc) 
= 0
  7035      3 mysqld   0.000008381 gettimeofday(0xba3ff3dc, 0) called
  7035      3 mysqld   0.000002794 gettimeofday(0xba3ff3dc, 0) = 0
  7035      3 mysqld   0.000006704 read(0x14, 0xbb7a1000, 0x4) called
  7035      3 mysqld   0.000002794 read(0x14, 0xbb7a1000, 0x4) Err#35 EAGAIN
  7035      3 mysqld   0.000002794 gettimeofday(0xba3ffa0c, 0) called
  7035      3 mysqld   0.000002235 gettimeofday(0xba3ffa0c, 0) = 0
  7035      3 mysqld   0.000001956 __sigprocmask14(0x1, 0x84e6f30, 0xba3ffa40) 
called
  7035      3 mysqld   0.000002235 __sigprocmask14(0x1, 0x84e6f30, 0xba3ffa40) 
= 0
  7035      3 mysqld   0.000003352 _lwp_kill(0x2, 0xe) called
  7035      3 mysqld   0.000003632 _lwp_kill(0x2, 0xe) = 0
  7035      2 mysqld   0.000006705 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0) = 
0
  7035      2 mysqld   0.000003911 __sigprocmask14(0x3, 0x84e6f30, 0xba5ffd30) 
called
  7035      2 mysqld   0.000001676 __sigprocmask14(0x3, 0x84e6f30, 0xba5ffd30) 
= 0
  7035      2 mysqld   0.000002794 _lwp_park(0, 0, 0x84e6f10, 0x84e6f10) 
called
  7035      3 mysqld   0.197895183 _lwp_unpark(0x2, 0x84e6f10) called
  7035      3 mysqld   0.000006705 _lwp_unpark(0x2, 0x84e6f10) = 0
  7035      2 mysqld   0.000005029 _lwp_park(0, 0, 0x84e6f10, 0x84e6f10) = 0
  7035      2 mysqld   0.000004190 gettimeofday(0xba5ffcdc, 0) called
  7035      2 mysqld   0.000003912 gettimeofday(0xba5ffcdc, 0) = 0
  7035      2 mysqld   0.000004749 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) called
  7035      2 mysqld   0.000005029 setitimer(0, 0xba5ffcd8, 0xba5ffcc8) = 0
  7035      2 mysqld   0.000002235 __sigprocmask14(0x3, 0xba5ffd30, 0) called
  7035      2 mysqld   0.000003073 __sigprocmask14(0x3, 0xba5ffd30, 0) = 0
  7035      2 mysqld   0.000005587 __sigtimedwait(0xba5ffd88, 0xba5ffcbc, 0) 
called
  7035      3 mysqld   0.000006426 __sigprocmask14(0x3, 0xba3ffa40, 0) called
  7035      3 mysqld   0.000001676 __sigprocmask14(0x3, 0xba3ffa40, 0) = 0
  7035      3 mysqld   0.000004470 fcntl(0x14, 0x4, 0x2) called
  7035      3 mysqld   0.000003632 fcntl(0x14, 0x4, 0x2) = 0
  7035      3 mysqld   0.000003631 read(0x14, 0xbb7a1000, 0x4) called

Note the delays before the calls to getpid and _lwp_unpark.  These delays both 
happen after the client has been told that the insert is complete -- which is 
why the slowdown is only apparent on multiple queries.  I should point out 
that the above trace was done with softdep mounted file systems.  Softdep 
appears to exacerbate the problem.  (Note also that I'm using a slightly 
hacked version of ktruss which reports the call to and the return from each 
system call separately).

I'd appreciate suggestions for how to debug this further.

Thanks,
Sverre


Home | Main Index | Thread Index | Old Index