使用profile分析python mysqldb遇到的性能问题

rfyiamcool 2 Comments

今天聊聊，如何使用mysql profiling调试python mysqldb遇到的性能问题 ？

这两天有几个烂需求，各种各样的统计数据。其中sql语句中含有like 这样的模糊查询，本来这东西不复杂，但mysql like是需要用% %符号的，恰好python的string转义用的也是% …

爬虫太狠，注释下 python mysqldb性能分析的文章原文链接， http://xiaorui.cc/?p=1884

http://xiaorui.cc/2015/08/18/%E4%BD%BF%E7%94%A8profile%E5%88%86%E6%9E%90python-mysqldb%E9%81%87%E5%88%B0%E7%9A%84%E6%80%A7%E8%83%BD%E9%97%AE%E9%A2%98/

这样就造成了不是语法的出错，就是可以顺利执行，但是无法获取正常的数据，蛋疼万分。
还有的时候是，我要确认下sql语句在mysql端到底有没有执行，我相信有些朋友也遇到过这样的问题。 除此之外，还有一个更重要的就是性能问题。要分析出这条sql语句，消耗了多少cpu io。

 当然排查问题的手段有很多，我可以直接mysql -h那台msyql服务器，然后show processlist;查看 。但是processlist是正在执行的，如果我这边的语句本来就很快，就看不到sql语句了。 

对于那种sql拼装的问题，或者是日志的记录都可以用cursor._last_executed来结局。 看名字你就知道他是干嘛的？ 上次执行的语句。

try:
    cursor.execute(sql, (arg1, arg2))
    connection.commit()
except:
    print cursor._last_executed
    raise " xiaorui.cc "

下面是是mysqldb输出cursor._last_executed的sql语句。  




	




	




另外我们可以在执行sql语句之前，先执行set profiling = 1 ,让他执行调试模式，当然结束之后最好关闭。


cursor.execute('set profiling = 1')
try:
    cursor.execute('SELECT * FROM xiaorui.cc where url = %s',['xiaorui.cc'])
except Exception:
    cursor.execute('show profiles')
    for row in cursor:
        print(row)        
cursor.execute('set profiling = 0')


我们可以看到每条语句的详细的执行流程。 可以看到autocommit=0 ,那么说明如果你的sql预计是insert update delete类型的，就需要cursor.commit()提交事物的。 


select count(id) from article where url like '%qq.com%' and created_on between '2015-08-17 13:00' and '2015-08-17 14:00'
(1L, 0.000125, u'SET NAMES utf8')
(2L, 0.00010225, u'set autocommit=0')
(3L, 0.000101, u'set profiling = 1')
(4L, 8.475e-05, u'SHOW WARNINGS')
(5L, 0.87501475, u"select count(id) from article where url like '%qq.com%' and created_on between '2015-08-17 10:00' and '2015-08-17 11:00'")
(6L, 0.0004955, u'SHOW WARNINGS')
(7L, 0.8820105, u"select count(id) from article where url like '%qq.com%' and created_on between '2015-08-17 11:00' and '2015-08-17 12:00'")
(8L, 0.000444, u'SHOW WARNINGS')
(9L, 0.88705, u"select count(id) from article where url like '%qq.com%' and created_on between '2015-08-17 12:00' and '2015-08-17 13:00'")
(10L, 0.00042825, u'SHOW WARNINGS')




我们可以用show profile for query sql号码，来详细查看每条sql语句的信息。默认只是打印一些时间的消耗。 


cursor.execute('show profile for query 2')

(u'starting', Decimal('0.000040'))
(u'Opening tables', Decimal('0.000010'))
(u'query end', Decimal('0.000005'))
(u'closing tables', Decimal('0.000004'))
(u'freeing items', Decimal('0.000027'))
(u'cleaning up', Decimal('0.000016'))



我们可以传递更多的show profile参数。 


SHOW PROFILE [type [, type] … ] [FOR QUERY n]   [LIMIT row_count [OFFSET offset]]


type:

ALL  (所有字段)

| BLOCK IO

| CONTEXT SWITCHES

| CPU

| IPC

| MEMORY

| PAGE FAULTS

| SOURCE

| SWAPS


type是可选的，取值范围可以如下：


ALL 显示所有性能信息

BLOCK IO 显示块IO操作的次数

CONTEXT SWITCHES 显示上下文切换次数，不管是主动还是被动

CPU 显示用户CPU时间、系统CPU时间

IPC 显示发送和接收的消息数量

PAGE FAULTS 显示页错误数量

SOURCE 显示源码中的函数名称与位置

SWAPS 显示SWAP的交互次数



那我们再来看看每条sql语句他的IO操作的次数。  当然如果直接用cursor.fetchall() 打印结果，你会看得发蒙。 需要你自己对照官方的文档。对比每个字段是什么意思的。 




cursor.execute('show profile BLOCK IO for query 1')


select count(id) from article where url like '%qq.com%' and created_on between '2015-08-17 11:00' and '2015-08-17 12:00'
((u'starting', Decimal('0.000057'), 0L, 0L), (u'Opening tables', Decimal('0.000010'), 0L, 0L), (u'query end', Decimal('0.000005'), 0L, 0L), (u'closing tables', Decimal('0.000005'), 0L, 0L), (u'freeing items', Decimal('0.000030'), 0L, 0L), (u'cleaning up', Decimal('0.000019'), 0L, 0L))
(u'starting', Decimal('0.000057'), 0L, 0L)
(u'Opening tables', Decimal('0.000010'), 0L, 0L)
(u'query end', Decimal('0.000005'), 0L, 0L)
(u'closing tables', Decimal('0.000005'), 0L, 0L)
(u'freeing items', Decimal('0.000030'), 0L, 0L)
(u'cleaning up', Decimal('0.000019'), 0L, 0L)



你可以现在mysql的cli终端下进行调试sql语句。  他的结果都是格式化好的， 所以你不用发愁像mysqldb驱动那样，需要自己来解析每个字段对照的意思。 


mysql> set profiling = 1;

Empty set, 1 warning (0.00 sec)


mysql> show variables like ‘%profili%’;

+————————+——-+

| Variable_name          | Value |

+————————+——-+

| have_profiling         | YES   |

| profiling              | ON    |

| profiling_history_size | 15    |

+————————+——-+

3 rows in set (0.00 sec)



mysql> show profile for query 11; 

+——————————–+————+ 

| Status | Duration | 

+——————————–+————+ 

| (initialization) | 0.00000425 | 

| checking query cache for query | 0.00004050 | 

| checking permissions | 0.00001050 | 

| Opening tables | 0.00018250 | 

| System lock | 0.00000450 | 

| Table lock | 0.00001775 | 

| init | 0.00001075 | 

| optimizing | 0.00000550 | 

| executing | 0.00002775 | 

| end | 0.00000450 | 

| query end | 0.00000325 | 

| storing result in query cache | 0.00000400 | 

| freeing items | 0.00000400 | 

| closing tables | 0.00000500 | 

| logging slow query | 0.00000300 | 

+——————————–+————+ 

15 rows in set (0.00 sec) 



mysql> show profile cpu for query 12;

+——————————+———–+———-+————+

| Status                       | Duration  | CPU_user | CPU_system |

+——————————+———–+———-+————+

| starting                     |  0.000183 | 0.000000 |   0.000000 |

| checking permissions         |  0.000057 | 0.000000 |   0.000000 |

| checking permissions         |  0.000059 | 0.000000 |   0.000000 |

| init                         |  0.000060 | 0.000000 |   0.000000 |

| Opening tables               |  0.000071 | 0.000000 |   0.000000 |

| System lock                  |  0.000062 | 0.000000 |   0.000000 |

| setup                        |  0.000080 | 0.000000 |   0.001000 |

| creating table               |  0.005052 | 0.003000 |   0.001000 |

| After create                 |  0.000220 | 0.000000 |   0.000000 |

| copy to tmp table            |  0.000244 | 0.000000 |   0.000000 |

| rename result table          | 11.364027 | 8.470864 |  43.612174 |

| end                          |  0.000575 | 0.000000 |   0.001000 |

| Waiting for query cache lock |  0.000062 | 0.000000 |   0.000000 |

| end                          |  0.000075 | 0.000000 |   0.000000 |

| query end                    |  0.000057 | 0.000000 |   0.000000 |

| closing tables               |  0.000061 | 0.000000 |   0.000000 |

| freeing items                |  0.000080 | 0.000000 |   0.000000 |

| logging slow query           |  0.000056 | 0.000000 |   0.000000 |

| logging slow query           |  0.000098 | 0.000000 |   0.000000 |

| cleaning up                  |  0.000059 | 0.000000 |   0.000000 |

+——————————+———–+———-+————+

20 rows in set (0.00 sec)



	




	显示sql语句执行所消耗的cpu及block io磁盘。 




mysql> show profile CPU,SWAPS,BLOCK IO for query 13;

+———————-+———-+———-+————+————–+—————+——-+

| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | Swaps |

+———————-+———-+———-+————+————–+—————+——-+

| starting             | 0.000694 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| checking permissions | 0.000044 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| Opening tables       | 0.000223 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| System lock          | 0.000127 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| init                 | 0.000238 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| optimizing           | 0.000035 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| statistics           | 0.000045 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| preparing            | 0.000022 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| executing            | 0.000013 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| Sending data         | 0.000418 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| end                  | 0.000020 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| query end            | 0.000008 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| closing tables       | 0.000227 | 0.002000 |   0.000000 |            0 |             0 |     0 |

| freeing items        | 0.001550 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| logging slow query   | 0.000012 | 0.000000 |   0.000000 |            0 |             0 |     0 |

| cleaning up          | 0.000017 | 0.000000 |   0.000000 |            0 |             0 |     0 |

+———————-+———-+———-+————+————–+—————+——-+

16 rows in set (0.00 sec)



	




	




	就先这样吧….   sql语句的性能优化要从各方面分析，比如 expain 索引命中情况，mysqlslowlog 慢日志。 




		        

            

            大家觉得文章对你有些作用！
                如果想赏钱，可以用微信扫描下面的二维码，感谢!
另外再次标注博客原地址  xiaorui.cc


            
                

        

	


	



				
	
			



			

			2 Responses		


		
    
			
	
  1. 
		
    
			
    
								docker				2015年8月27日 / 下午5:48
			
    

			
			
    
				
    好文！
    
			
    

			
    
								回复			
    
		
    

	
    2. 

	
  2. 
		
    
			
    
								米运维				2015年8月20日 / 上午7:49
			
    

			
			
    
				
    打印语句很有用
    
			
    

			
    
								回复			
    
		
    

	
    3. 
		


		
	
	
		

		
发表评论 
邮箱地址不会被公开。 必填项已用*标注