mysql tests - one more thing to try

[Joseph Koshy]

> here are ktrace results for supersmack and mysqld from a dualcore opteron box
> running select smack with 100 threads and 10000 queries
> os: fbsd 6.1 prerelease
>
> ==== syscall stats for supersmack ====
> number of syscalls captured:  42575687
> individual syscalls counts:
>    read   32914539  77.31%
>    gettimeofday   3865508  9.08%
>    fcntl   3862708  9.07%
>    write   1930922  4.54%
>    break   325  0.00%
>    close   301  0.00%
>    setsockopt   202  0.00%
>    select   192  0.00%
>    semop   184  0.00%
>    connect   101  0.00%
>    wait4   101  0.00%
>    socket   101  0.00%
>    getpid   100  0.00%
>    fork   100  0.00%
>    exit   97  0.00%
>    shutdown   96  0.00%
>    mmap   27  0.00%
>    access   15  0.00%
>    mprotect   12  0.00%
>    open   12  0.00%
>    fstat   10  0.00%
>    munmap   8  0.00%
>    execve   7  0.00%
>    ioctl   4  0.00%
>    stat   3  0.00%
>    sigprocmask   2  0.00%
>    issetugid   2  0.00%
>    lseek   1  0.00%
>    sysarch   1  0.00%
>    __sysctl   1  0.00%
>    semget   1  0.00%
>    readlink   1  0.00%
>    sigaction   1  0.00%
>    pipe   1  0.00%
>    __semctl   1  0.00%
>
> request sizes for syscall read
>   size  count   %
> ---------------------------
>    4    15489977  47.06%
>    50    3982797  12.10%
>    1    3873493  11.77%
>    52    2654645  8.07%
>    60    1937753  5.89%
>    5    1933249  5.87%
>    8192    1931176  5.87%
>    53    790179  2.40%
>    51    274285  0.83%
>    49    23467  0.07%
>    48    12943  0.04%
>    1023    5301  0.02%
>    47    2543  0.01%
>    46    2497  0.01%
>    7    101  0.00%
>    24    99  0.00%
>    4096    29  0.00%
>    128    1  0.00%
>    6    1  0.00%
>    17796    1  0.00%
>    30    1  0.00%
>    66    1  0.00%
>
> request sizes for syscall write
>   size  count   %
> ---------------------------
>    65    1716567  88.90%
>    64    193387  10.02%
>    63    20584  1.07%
>    47    101  0.01%
>    5    94  0.00%
>    4    92  0.00%
>    26    92  0.00%
>    34    1  0.00%
>    35    1  0.00%
>    40    1  0.00%
>    49    1  0.00%
>    55    1  0.00%
>
> ==== syscall stats for mysqld ====
>
> number of syscalls captured:  20743045
> individual syscalls counts:
>    _umtx_op   7657825  36.92%
>    gettimeofday   4308736  20.77%
>    read   4306035  20.76%
>    write   1942882  9.37%
>    sigprocmask   1680724  8.10%
>    fcntl   838247  4.04%
>    thr_kill   2827  0.01%
>    sigwait   2403  0.01%
>    setitimer   1669  0.01%
>    select   698  0.00%
>    setsockopt   202  0.00%
>    access   101  0.00%
>    accept   101  0.00%
>    getsockname   101  0.00%
>    open   101  0.00%
>    shutdown   96  0.00%
>    close   96  0.00%
>    thr_new   92  0.00%
>    thr_exit   87  0.00%
>    break   22  0.00%
>
> request sizes for syscall write
>   size  count   %
> ---------------------------
>    304    794935  40.92%
>    303    720255  37.07%
>    302    274534  14.13%
>    301    111278  5.73%
>    300    23412  1.21%
>    299    13079  0.67%
>    297    2615  0.13%
>    298    2571  0.13%
>    11    101  0.01%
>    56    101  0.01%
>    63    1  0.00%
> request sizes for syscall read
>   size  count   %
> ---------------------------
>    4    2362079  54.86%
>    61    1728044  40.13%
>    60    194721  4.52%
>    59    20993  0.49%
>    43    101  0.00%
>    1    96  0.00%
>    31    1  0.00%

Ganbold was kind enough to run a hwpmc profiling session while running
super-smack.

The kernel profile can be seen here:

  http://www.mnbsd.org/ftp/kernel_gprof.txt

Excerpt:

 granularity: each sample hit covers 4 byte(s) for 0.00% of 111655.00 seconds
 time is in ticks, not seconds
   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
   6.0    6664.00  6664.00        0  100.00%           syscall [1]
   4.1   11215.00  4551.00        0  100.00%           soreceive [2]
   4.1   15743.00  4528.00        0  100.00%           binuptime [3]
   3.1   19217.00  3474.00        0  100.00%           generic_copyout [4]
   2.7   22230.00  3013.00        0  100.00%           generic_copyin [5]

The profile for libmysql (http://www.mnbsd.org/ftp/libmysql_gprof.txt)
looked like:

 time is in ticks, not seconds
 granularity: each sample hit covers 4 byte(s) for 0.00% of 23377.00 seconds

   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
  12.2    2850.00  2850.00        0  100.00%           MD5Transform [1]
  11.3    5503.00  2653.00        0  100.00%           sha1_result [2]
   9.6    7752.00  2249.00        0  100.00%           my_once_alloc [3]
   7.7    9561.00  1809.00        0  100.00%           my_compress [4]
   6.8   11150.00  1589.00        0  100.00%           load_defaults [5]
   3.2   11904.00   754.00        0  100.00%           my_once_strdup [6]

These profiles are consistent with there being lots of short-lived
system calls.

Due to a shortcoming in the profiling toolset, Ganbold's run could not
capture what mysqld was doing.

--
FreeBSD Volunteer,     http://people.freebsd.org/~jkoshy