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