OProfile比较sql执行CPU消耗情况


OProfile is a system-wide profiler for Linux systems, capable of profiling all running code at low overhead. OProfile is released under the GNU GPL

oprofile定位代码性能问题的工具

第一种sql写法：

SELECT * FROM t WHERE user_id=10 LIMIT 400000,10
$sudo opcontrol --init
$sudo opcontrol --setup --separate=lib,kernel,thread --no-vmlinux
$sudo opcontrol --start-daemon
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/oprofiled.log
Daemon started.
$sudo opcontrol --start
Profiler running.
$time mysql -u root test<< EOF;
> select * from t where user_id=10 limit 400000,10;
> EOF
real    0m2.898s
user    0m0.008s
sys     0m0.002s
$sudo opcontrol --dump
$sudo opreport --demangle=smart --symbols --long-filenames --merge tgid $(which mysqld) | head -n 20
warning: /no-vmlinux could not be found.
CPU: Core 2, speed 1992 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 6000
samples  %        image name               symbol name
308374   40.0385  /lib64/tls/libc-2.3.4.so memcpy
61705     8.0116  /u01/mysql/libexec/mysqld row_sel_store_mysql_rec
57988     7.5290  /lib64/tls/libc-2.3.4.so memset
25651     3.3305  /u01/mysql/libexec/mysqld rec_get_offsets_func
23232     3.0164  /lib64/tls/libpthread-2.3.4.so pthread_mutex_trylock
22879     2.9706  /u01/mysql/libexec/mysqld btr_search_guess_on_hash
19499     2.5317  /lib64/tls/libpthread-2.3.4.so pthread_mutex_unlock
18479     2.3993  /u01/mysql/libexec/mysqld row_search_for_mysql
9393      1.2196  /u01/mysql/libexec/mysqld cmp_dtuple_rec_with_match
9053      1.1754  /u01/mysql/libexec/mysqld select_send::send_data(List<Item>&)
8259      1.0723  /u01/mysql/libexec/mysqld mem_pool_fill_free_list
7844      1.0184  /u01/mysql/libexec/mysqld Protocol_simple::store(Field*)
7755      1.0069  /u01/mysql/libexec/mysqld MYSQLparse(void*)
5823      0.7560  /u01/mysql/libexec/mysqld mtr_memo_slot_release
4841      0.6285  /u01/mysql/libexec/mysqld anonymous symbol from section .plt
4669      0.6062  /u01/mysql/libexec/mysqld my_longlong10_to_str_8bit
4610      0.5986  /u01/mysql/libexec/mysqld Protocol::net_store_data(char const*, unsigned int)
$sudo opcontrol --stop
$sudo opcontrol --deinit
Stopping profiling.
Killing daemon.
Unloading oprofile module
$sudo opcontrol --reset

第二种sql写法：

SELECT *                                                            
  FROM (SELECT id FROM t WHERE user_id = 10 LIMIT 400000, 10) a, t b
 WHERE a.id = b.id;
$sudo opcontrol --init
$sudo opcontrol --setup --separate=lib,kernel,thread --no-vmlinux
$sudo opcontrol --start-daemon
$sudo opcontrol --start
$time mysql -u root test << EOF;
> select *
>   from (select id from t where user_id = 10 limit 400000, 10) a, t b
>  where a.id = b.id;
> EOF
 
real    0m1.214s
user    0m0.010s
sys     0m0.001s
 
 
$sudo opcontrol --dump
$sudo opreport --demangle=smart --symbols --long-filenames --merge tgid $(which mysqld) | head -n 20
warning: /no-vmlinux could not be found.
CPU: Core 2, speed 1992 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 6000
samples  %        image name               symbol name
170549   42.5976  /lib64/tls/libc-2.3.4.so memcpy
29998     7.4925  /u01/mysql/libexec/mysqld row_sel_store_mysql_rec
24308     6.0714  /lib64/tls/libc-2.3.4.so memset
13637     3.4061  /u01/mysql/libexec/mysqld rec_get_offsets_func
13469     3.3641  /u01/mysql/libexec/mysqld row_search_for_mysql
13440     3.3569  /lib64/tls/libpthread-2.3.4.so pthread_mutex_trylock
8477      2.1173  /u01/mysql/libexec/mysqld btr_search_guess_on_hash
8244      2.0591  /lib64/tls/libpthread-2.3.4.so pthread_mutex_unlock
6492      1.6215  /u01/mysql/libexec/mysqld cmp_dtuple_rec_with_match
4611      1.1517  /u01/mysql/libexec/mysqld MYSQLparse(void*)
2744      0.6854  /u01/mysql/libexec/mysqld mtr_memo_slot_release
2641      0.6596  /u01/mysql/libexec/mysqld buf_page_optimistic_get_func
2508      0.6264  /u01/mysql/libexec/mysqld btr_cur_search_to_nth_level
2332      0.5825  /u01/mysql/libexec/mysqld mem_pool_fill_free_list
2272      0.5675  /u01/mysql/libexec/mysqld sync_array_print_long_waits
2217      0.5537  /u01/mysql/libexec/mysqld btr_pcur_store_position
2187      0.5462  /u01/mysql/libexec/mysqld anonymous symbol from section .plt
 
$sudo opcontrol --stop
$sudo opcontrol --deinit
$sudo opcontrol --reset

参考：http://www.fromdual.ch/mysql-oprofile

vmtouch


有同学在邮件里问，为什么放binlog的磁盘没有读操作，slave肯定是要读取binlog的,后来褚霸用小工具vmtouch，证明slave读取binlog是从file system cache读取，所以没看到磁盘的读操作。于是安装这个工具，玩了一下，具体可以参考http://hoytech.com/vmtouch/

$vmtouch
vmtouch v0.7.3 - the Virtual Memory Toucher by Doug Hoyte
Portable file system cache diagnostics and control
 
Usage: vmtouch [OPTIONS] ... FILES OR DIRECTORIES ...
 
Options:
  -t touch pages into memory
  -e evict pages from memory
  -l lock pages in physical memory with mlock(2)
  -L lock pages in physical memory with mlockall(2)
  -d daemon mode
  -m <size> max file size to touch
  -f follow symbolic links
  -v verbose
  -q quiet
 
[No-Mysql@xx ~]
$echo 'aa' > test.txt
 
[No-Mysql@xx ~]
$vmtouch -v test.txt
test.txt
[O] 1/1
 
           Files: 1
     Directories: 0
  Resident Pages: 1/1  4K/4K  100%
         Elapsed: 9.1e-05 seconds
 
[No-Mysql@xx ~]
$vmtouch -e test.txt
           Files: 1
     Directories: 0
   Evicted Pages: 1 (4K)
         Elapsed: 4.1e-05 seconds
 
[No-Mysql@xx ~]
$vmtouch -v test.txt
test.txt
[ ] 0/1
 
           Files: 1
     Directories: 0
  Resident Pages: 0/1  0/4K  0%
         Elapsed: 8.5e-05 seconds

tcprstat


tcprstat是percona开发工具，主要用来观察请求的响应时间

具体参考：

http://www.percona.com/docs/wiki/tcprstat:start
http://blog.yufeng.info/archives/963#more-963
$sudo tcprstat -p 3306 -t 1 -n 0 -l `/sbin/ifconfig | grep 'addr:[^ ]\+' -o | cut -f 2 -d : | xargs echo | sed -e 's/ /,/g'`
timestamp       count   max     min     avg     med     stddev  95_max  95_avg  95_std  99_max  99_avg  99_std
1323926388      26      1158    239     358     315     178     482     318     75      510     326     81
1323926389      24      1317    231     362     261     227     481     304     83      679     320     112
1323926390      42      1204    43      274     251     193     458     238     117     529     252     127
1323926391      27      960     100     315     256     151     436     284     74      469     291     81

CPU saturation



当看到r的值很大，但id又是闲置的，可能原因：在较短期间运行的队列很长，其后是闲置时间，在间隔时间内产生非零运行队列和闲置时间。

间隔时间理解：
5%利用率感觉系统很空闲，但这个时间间隔在是60分钟。如果这个发生在3分钟之内呢？这个利用率就会达到100%，所以利用率要和时间相结合来进行评估。

linux命令随记


Q:如何得到进程ID
A1:

[root@dg1 ~]# 
ps -eaf | grep -w 'mysqld' | grep -v mysqld_safe | awk '{print $2}' | head -n1
5737

A2:

[root@dg1 ~]# pidof mysqld
5737

A3:

[root@dg1 ~]# pgrep -o -x mysqld
5737

Q:flock保护shell脚本中部分代码串行化
A:

#!/bin/sh
(
 flock -n -x 200
 if [ $? -ne 0 ] ;then
 echo "The script is running already."
 exit
 fi
 sleep 10  #you command here
 ) 200>/tmp/flock >> "/tmp/flock.log" 2>&1

Q: pmap显示真正使用内存
A:

[root@dg1 ~]# pmap -x  5737
total kB  329572

注意：

[root@dg1 ~]# ps -aux|grep mysqld

显示使用内存数往往大于pmap显示的，因为ps显示内存数中包含了共享内存