RE: Further FreeBSD 4.3 Issues (CPU hogging)

[Institute For Social Ecology]

Ken,

Thanks as always for your very helpful support.  I did a 'truss -p' on
the PID and it came back empty handed.  I did do a 'truss
/usr/local/libexec/mysqld' which spat back all sorts of goodies.  I
have included the output bellow.  Also, as requested, below is the
output of mysqlbug.

Once again, thank you for your help.

Regards,

Michael

truss /usr/local/libexec/mysqld:

__sysctl(0xbfbffac4,0x2,0x281bfba8,0xbfbffac0,0x0,0x0) = 0 (0x0)
mmap(0x0,32768,0x3,0x1002,-1,0x0)                = 672927744
(0x281c1000)
geteuid()                                        = 1048 (0x418)
getuid()                                         = 1048 (0x418)
getegid()                                        = 1048 (0x418)
getgid()                                         = 1048 (0x418)
open("/var/run/ld-elf.so.hints",0,00)            = 3 (0x3)
read(0x3,0xbfbffaa4,0x80)                        = 128 (0x80)
lseek(3,0x80,0)                                  = 128 (0x80)
read(0x3,0x281c5000,0x3d)                        = 61 (0x3d)
close(3)                                         = 0 (0x0)
access("/usr/lib/libwrap.so.3",0)                = 0 (0x0)
open("/usr/lib/libwrap.so.3",0,027757775434)     = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,32768,0x5,0x2,3,0x0)                    = 672960512
(0x281c9000)
mmap(0x281cf000,4096,0x3,0x12,3,0x5000)          = 672985088
(0x281cf000)
mmap(0x281d0000,4096,0x3,0x1012,-1,0x0)          = 672989184
(0x281d0000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libz.so.2",0)                   = 0 (0x0)
open("/usr/lib/libz.so.2",0,027757775434)        = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,53248,0x5,0x2,3,0x0)                    = 672993280
(0x281d1000)
mmap(0x281dc000,8192,0x3,0x12,3,0xa000)          = 673038336
(0x281dc000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libcrypt.so.2",0)               = 0 (0x0)
open("/usr/lib/libcrypt.so.2",0,027757775434)    = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,102400,0x5,0x2,3,0x0)                   = 673046528
(0x281de000)
mmap(0x281e5000,4096,0x3,0x12,3,0x6000)          = 673075200
(0x281e5000)
mmap(0x281e6000,69632,0x3,0x1012,-1,0x0)         = 673079296
(0x281e6000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libstdc++.so.3",0)              = 0 (0x0)
open("/usr/lib/libstdc++.so.3",0,027757775434)   = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,282624,0x5,0x2,3,0x0)                   = 673148928
(0x281f7000)
mmap(0x28239000,12288,0x3,0x12,3,0x41000)        = 673419264
(0x28239000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libm.so.2",0)                   = 0 (0x0)
open("/usr/lib/libm.so.2",0,027757775434)        = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,110592,0x5,0x2,3,0x0)                   = 673431552
(0x2823c000)
mmap(0x28253000,16384,0x3,0x12,3,0x16000)        = 673525760
(0x28253000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libc_r.so.4",0)                 = 0 (0x0)
open("/usr/lib/libc_r.so.4",0,027757775434)      = 3 (0x3)
fstat(3,0xbfbffaec)                              = 0 (0x0)
read(0x3,0xbfbfeabc,0x1000)                      = 4096 (0x1000)
mmap(0x0,741376,0x5,0x2,3,0x0)                   = 673542144
(0x28257000)
mmap(0x282ed000,20480,0x3,0x12,3,0x95000)        = 674156544
(0x282ed000)
mmap(0x282f2000,106496,0x3,0x1012,-1,0x0)        = 674177024
(0x282f2000)
close(3)                                         = 0 (0x0)
access("/usr/lib/libm.so.2",0)                   = 0 (0x0)
sigaction(SIGILL,0xbfbffb44,0xbfbffb2c)          = 0 (0x0)
sigprocmask(0x1,0x0,0x281bfadc)                  = 0 (0x0)
sigaction(SIGILL,0xbfbffb2c,0x0)                 = 0 (0x0)
getpid()                                         = 980 (0x3d4)
fcntl(0x0,0x3,0x0)                               = 2 (0x2)
fcntl(0x1,0x3,0x0)                               = 2 (0x2)
fcntl(0x2,0x3,0x0)                               = 2 (0x2)
pipe()                                           = 3 (0x3)
fcntl(0x3,0x3,0x0)                               = 2 (0x2)
fcntl(0x3,0x4,0x6)                               = 0 (0x0)
fcntl(0x4,0x3,0x0)                               = 2 (0x2)
fcntl(0x4,0x4,0x6)                               = 0 (0x0)
readlink("/etc/malloc.conf",0xbfbff9b8,63)       ERR#2 'No such file
or directory'
mmap(0x0,4096,0x3,0x1002,-1,0x0)                 = 674283520
(0x2830c000)
break(0x81d3000)                                 = 0 (0x0)
break(0x81d4000)                                 = 0 (0x0)
break(0x81d5000)                                 = 0 (0x0)
break(0x81d6000)                                 = 0 (0x0)
mmap(0xbfaff000,4096,0x0,0x1000,-1,0x0)          = -1078988800
(0xbfaff000)
gettimeofday(0x282ee988,0x0)                     = 0 (0x0)
break(0x81e0000)                                 = 0 (0x0)
sigaltstack(0x2830a3a0,0x0)                      = 0 (0x0)
sigaction(SIGHUP,0x0,0x28306c20)                 = 0 (0x0)
sigaction(SIGINT,0x0,0x28306c38)                 = 0 (0x0)
sigaction(SIGQUIT,0x0,0x28306c50)                = 0 (0x0)
sigaction(SIGILL,0x0,0x28306c68)                 = 0 (0x0)
sigaction(SIGTRAP,0x0,0x28306c80)                = 0 (0x0)
sigaction(SIGABRT,0x0,0x28306c98)                = 0 (0x0)
sigaction(SIGEMT,0x0,0x28306cb0)                 = 0 (0x0)
sigaction(SIGFPE,0x0,0x28306cc8)                 = 0 (0x0)
sigaction(SIGBUS,0x0,0x28306cf8)                 = 0 (0x0)
sigaction(SIGSEGV,0x0,0x28306d10)                = 0 (0x0)
sigaction(SIGSYS,0x0,0x28306d28)                 = 0 (0x0)
sigaction(SIGPIPE,0x0,0x28306d40)                = 0 (0x0)
sigaction(SIGALRM,0x0,0x28306d58)                = 0 (0x0)
sigaction(SIGTERM,0x0,0x28306d70)                = 0 (0x0)
sigaction(SIGURG,0x0,0x28306d88)                 = 0 (0x0)
sigaction(SIGTSTP,0x0,0x28306db8)                = 0 (0x0)
sigaction(SIGCONT,0x0,0x28306dd0)                = 0 (0x0)
sigaction(SIGCHLD,0x0,0x28306de8)                = 0 (0x0)
sigaction(SIGTTIN,0x0,0x28306e00)                = 0 (0x0)
sigaction(SIGTTOU,0x0,0x28306e18)                = 0 (0x0)
sigaction(SIGIO,0x0,0x28306e30)                  = 0 (0x0)
sigaction(SIGXCPU,0x0,0x28306e48)                = 0 (0x0)
sigaction(SIGXFSZ,0x0,0x28306e60)                = 0 (0x0)
sigaction(SIGVTALRM,0x0,0x28306e78)              = 0 (0x0)
sigaction(SIGPROF,0x0,0x28306e90)                = 0 (0x0)
sigaction(SIGWINCH,0x0,0x28306ea8)               = 0 (0x0)
sigaction(SIGINFO,0x0,0x28306ec0)                = 0 (0x0)
sigaction(SIGUSR1,0x0,0x28306ed8)                = 0 (0x0)
sigaction(SIGUSR2,0x0,0x28306ef0)                = 0 (0x0)
sigaction(SIGPROF,0xbfbffa9c,0x0)                = 0 (0x0)
sigaction(SIGINFO,0xbfbffa9c,0x0)                = 0 (0x0)
sigaction(SIGCHLD,0xbfbffa9c,0x0)                = 0 (0x0)
sigprocmask(0x3,0x0,0x282ee9f8)                  = 0 (0x0)
__sysctl(0xbfbffa94,0x2,0xbfbffab4,0xbfbffa90,0x0,0x0) = 0 (0x0)
getdtablesize()                                  = 2440 (0x988)
break(0x81e3000)                                 = 0 (0x0)
break(0x81e8000)                                 = 0 (0x0)
break(0x81e9000)                                 = 0 (0x0)
fcntl(0x0,0x4,0x6)                               = 0 (0x0)
fcntl(0x1,0x4,0x6)                               = 0 (0x0)
fcntl(0x2,0x4,0x6)                               = 0 (0x0)
break(0x81ea000)                                 = 0 (0x0)
sigprocmask(0x1,0x281bfaa0,0xbfbffb6c)           = 0 (0x0)
sigprocmask(0x3,0x281bfab0,0x0)                  = 0 (0x0)
access("/etc/localtime",4)                       = 0 (0x0)
open("/etc/localtime",0,00)                      = 5 (0x5)
fcntl(0x5,0x3,0x0)                               = 0 (0x0)
fcntl(0x5,0x4,0x4)                               = 0 (0x0)
fstat(5,0xbfbff788)                              = 0 (0x0)
read(0x5,0xbfbfd47c,0x1f08)                      = 1000 (0x3e8)
fstat(5,0xbfbfd3c8)                              = 0 (0x0)
fcntl(0x5,0x3,0x0)                               = 4 (0x4)
fcntl(0x5,0x4,0x0)                               = 0 (0x0)
close(5)                                         = 0 (0x0)
gettimeofday(0xbfbff880,0x0)                     = 0 (0x0)
__sysctl(0xbfbff870,0x2,0x81cbe00,0xbfbff86c,0x0,0x0) = 0 (0x0)
break(0x81eb000)                                 = 0 (0x0)
open("/etc/my.cnf",0,00)                         = 5 (0x5)
fcntl(0x5,0x3,0x0)                               = 0 (0x0)
fcntl(0x5,0x4,0x4)                               = 0 (0x0)
fstat(5,0xbfbff298)                              = 0 (0x0)
break(0x81ed000)                                 = 0 (0x0)
read(0x5,0x81eb000,0x2000)                       = 2500 (0x9c4)
break(0x81ee000)                                 = 0 (0x0)
read(0x5,0x81eb000,0x2000)                       = 0 (0x0)
fstat(5,0xbfbff2a8)                              = 0 (0x0)
fcntl(0x5,0x3,0x0)                               = 4 (0x4)
fcntl(0x5,0x4,0x0)                               = 0 (0x0)
close(5)                                         = 0 (0x0)
open("/var/db/mysql/my.cnf",0,00)                ERR#13 'Permission
denied'
open("/home/ise/.my.cnf",0,00)                   ERR#2 'No such file
or directory'
/usr/local/libexec/mysqld: Too many parameters
write(2,0xbfbff060,47)                           = 47 (0x2f)
fstat(1,0xbfbff3a8)                              = 0 (0x0)
ioctl(1,TIOCGETA,0xbfbff3dc)                     = 0 (0x0)
/usr/local/libexec/mysqld  Ver 3.23.39 for -freebsd4.2 on i386
write(1,0x81d4800,63)                            = 63 (0x3f)
Use '--help' or '--no-defaults --help' for a list of available options
write(1,0x81d4800,71)                            = 71 (0x47)
sigprocmask(0x1,0x281bfaa0,0xbfbff6e8)           = 0 (0x0)
sigprocmask(0x3,0x281bfab0,0x0)                  = 0 (0x0)
setitimer(0x2,0xbfbff708,0x0)                    = 0 (0x0)
close(3)                                         = 0 (0x0)
close(4)                                         = 0 (0x0)
fcntl(0x0,0x3,0x0)                               = 6 (0x6)
fcntl(0x0,0x4,0x2)                               = 0 (0x0)
fcntl(0x1,0x3,0x0)                               = 2 (0x2)
fcntl(0x1,0x4,0x2)                               = 0 (0x0)
fcntl(0x2,0x3,0x0)                               = 2 (0x2)
fcntl(0x2,0x4,0x2)                               = 0 (0x0)
exit(0x1)                                       process exit, rval =
256


mysqlbugreort:

SEND-PR: -*- send-pr -*-
SEND-PR: Lines starting with `SEND-PR' will be removed automatically,
as
SEND-PR: will all comments (text enclosed in `<' and `>').
SEND-PR:
From: ise
To: mysql@stripped
Subject: [50 character or so descriptive subject here (for reference)]

>Description:
        <precise description of the problem (multiple lines)>
>How-To-Repeat:
        <code/input/activities to reproduce the problem (multiple
lines)>
>Fix:
        <how to correct or work around the problem, if known (multiple
lines)>

>Submitter-Id:  <submitter ID>
>Originator:    ISE
>Organization:
 <organization of PR author (multiple lines)>
>MySQL support: [none | licence | email support | extended email
support ]
>Synopsis:      <synopsis of the problem (one line)>
>Severity:      <[ non-critical | serious | critical ] (one line)>
>Priority:      <[ low | medium | high ] (one line)>
>Category:      mysql
>Class:         <[ sw-bug | doc-bug | change-request | support ] (one
line)>
>Release:       mysql-3.23.39 (Source distribution)

>Environment:
        <machine, os, target, libraries (multiple lines)>
System: FreeBSD flag.blackened.net 4.3-STABLE FreeBSD 4.3-STABLE #0:
Tue Jul 24 22:02:37 PDT 2001
root@stripped:/usr/src/sys/compile/FLAG  i386


Some paths:  /usr/bin/perl /usr/bin/make /usr/local/bin/gmake
/usr/bin/gcc /usr/bin/cc
GCC: Using builtin specs.
gcc version 2.95.3 [FreeBSD] 20010315 (release)
Compilation info: CC='cc'  CFLAGS='-O -pipe '  CXX='c++'
 CXXFLAGS='-O -pipe  -felide-constructors -fno-rtti -fno-exceptions'
LDFLAGS=''
LIBC:
-r--r--r--  1 root  wheel  1202644 Jul 18 04:17 /usr/lib/libc.a
lrwxr-xr-x  1 root  wheel  9 Jul 18 04:17 /usr/lib/libc.so ->
libc.so.4
-r--r--r--  1 root  wheel  520516 Mar 16  2000 /usr/lib/libc.so.3
-r--r--r--  1 root  wheel  570968 Jul 18 04:17 /usr/lib/libc.so.4
Configure command:
./configure  --localstatedir=/var/db/mysql --without-perl --without-de
bug --without-readline --without-bench --with-mit-threads=no --with-li
bwrap --with-low-memory --enable-assembler --with-berkeley-db --prefix
=/usr/local i386--freebsd4.2
Perl: This is perl, version 5.005_03 built for i386-freebsd



-----Original Message-----
From: Ken Menzel [mailto:kenm@stripped]
Sent: Wednesday, August 01, 2001 4:28 PM
To: ise@stripped; mysql@stripped
Subject: Re: Further FreeBSD 4.3 Issues (CPU hogging)


Hi Michael,
  Umm very odd behavior,  I prresume you have already killed and
restarted this process?  But if not can use use 'truss' to trace the
system calls being made by the process now?  (truss -p
pid-of-process -o output-file).  Just get a few seconds worth.  Also
can you run the 'mysqlbug' command and just exit from vi with changing
anything and send the  /tmp/failed-mysql-bugreport file.  Remember
FreeBSD 4.2-release does have threads bugs.  Your application may be
different than mine,  so you have found a bug that I haven't come
across.  Although from the mysql processlist you sent it looks like
there are no queries running,  so something odd is happening.   Lets
start with the output of mysqlbug and truss.
Ken
----- Original Message -----
From: "Institute For Social Ecology" <ise@stripped>
To: <kenm@stripped>; <mysql@stripped>
Sent: Wednesday, August 01, 2001 3:22 PM
Subject: Further FreeBSD 4.3 Issues (CPU hogging)


> Ken and all,
>
> I wrote around a month back about some problems I was having with my
> MySQL install in a freeBSD 4.2 system.  I received allot of helpful
> advice on troubleshooting the problems (memory hogging issues).
> Thanks to all.  To date, we have recently upgraded to mysqld Ver
> 3.23.39 for freebsd4.2, and freeBSD 4.3.
>
> The problem I am now experiencing relates to CPU hogging.  When we
did
> the above upgrade, mysqld seemed to be acting reasonable in terms of
> it's CPU and memory usage.  For whatever reason, mysqld is now
> occupying 92.48% of one of our 266 mhz processors, even though
mysqld
> is presently receiving only 1-5 queries per minute (and pretty
simple
> queries at that).
>
> Why then is mysqld taking up 92.48% of one of our processors, when a
> week back it was taking up on average 10%?
>
> I have included some output below that might be of use.  Any insight
> would be of great help.
>
> Regards,
>
> Michael Caplan
> Institute for Social Ecology
>
> 1118 Maple Hill Rd.
> Plainfield, Vermont, 05667
> USA
>
> Tel./Fax. [phone]
>
> http://www.social-ecology.org/
>
>
> Mem: 34M Active, 2240K Inact, 20M Wired, 4156K Cache, 15M Buf, 884K
> Free
> Swap: 260M Total, 40M Used, 219M Free, 15% Inuse, 20K In
>
>   PID USERNAME PRI NICE  SIZE    RES STATE  C   TIME   WCPU    CPU
> COMMAND
>   537 mysql     56   0 39388K  2460K CPU1   1  98.8H 92.48% 92.48%
> mysqld
>
>
> Processes running:
>
>
+-------+-------+-----------+------+---------+------+-------+---------
> ---------+
> | Id    | User  | Host      | db   | Command | Time | State | Info
> |
>
+-------+-------+-----------+------+---------+------+-------+---------
> ---------+
> | 17665 | jan   | localhost | jan  | Sleep   | 626  |       |
> |
> | 17671 | daver | localhost | flag | Sleep   | 452  |       |
> |
> | 17672 | daver | localhost | flag | Sleep   | 167  |       |
> |
> | 17675 | daver | localhost | flag | Sleep   | 86   |       |
> |
> | 17676 | daver | localhost | flag | Sleep   | 136  |       |
> |
> | 17682 | root  | localhost |      | Query   | 0    |       | show
> processlist |
>
+-------+-------+-----------+------+---------+------+-------+---------
> ---------+
>
>
>
> +--------------------------+----------+
> | Variable_name            | Value    |
> +--------------------------+----------+
> | Aborted_clients          | 2954     |
> | Aborted_connects         | 3        |
> | Bytes_received           | 16332450 |
> | Bytes_sent               | 51625490 |
> | Connections              | 17684    |
> | Created_tmp_disk_tables  | 0        |
> | Created_tmp_tables       | 348      |
> | Created_tmp_files        | 0        |
> | Delayed_insert_threads   | 0        |
> | Delayed_writes           | 0        |
> | Delayed_errors           | 0        |
> | Flush_commands           | 2        |
> | Handler_delete           | 428      |
> | Handler_read_first       | 2605     |
> | Handler_read_key         | 97129    |
> | Handler_read_next        | 618052   |
> | Handler_read_prev        | 273      |
> | Handler_read_rnd         | 194703   |
> | Handler_read_rnd_next    | 3373669  |
> | Handler_update           | 46570    |
> | Handler_write            | 13392    |
> | Key_blocks_used          | 801      |
> | Key_read_requests        | 607043   |
> | Key_reads                | 572      |
> | Key_write_requests       | 14286    |
> | Key_writes               | 5834     |
> | Max_used_connections     | 31       |
> | Not_flushed_key_blocks   | 0        |
> | Not_flushed_delayed_rows | 0        |
> | Open_tables              | 99       |
> | Open_files               | 184      |
> | Open_streams             | 0        |
> | Opened_tables            | 228      |
> | Questions                | 209184   |
> | Select_full_join         | 6        |
> | Select_full_range_join   | 0        |
> | Select_range             | 785      |
> | Select_range_check       | 0        |
> | Select_scan              | 16327    |
> | Slave_running            | OFF      |
> | Slave_open_temp_tables   | 0        |
> | Slow_launch_threads      | 1        |
> | Slow_queries             | 0        |
> | Sort_merge_passes        | 0        |
> | Sort_range               | 17111    |
> | Sort_rows                | 192823   |
> | Sort_scan                | 8413     |
> | Table_locks_immediate    | 92585    |
> | Table_locks_waited       | 91       |
> | Threads_cached           | 0        |
> | Threads_created          | 17683    |
> | Threads_connected        | 6        |
> | Threads_running          | 1        |
> | Uptime                   | 582432   |
> +--------------------------+----------+
>
>