使用Profile抓住慢查询

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 在很多情况下,DBA都要对数据库的性能进行分析处理,找出降低性能的根源而Mongo就有一种分析工具来检测并追踪影响性能的慢查询---Profile有两种方式可以控制Profiling的开关和级别,第一种是直接在启动参数中进行设置,如下:如果想要全局开启Profiling,则可以在mongod启动时加上参数mongod --profile 1 --slowms 100 # 1表示追踪级别,100表示慢查询判定时间(ms)若是配置文件中开启的话,配置如下:operationProfiling: slowOpThresholdMs: 100 mode: s

在很多情况下,DBA都要对数据库的性能进行分析处理,找出降低性能的根源
而Mongo就有一种分析工具来检测并追踪影响性能的慢查询---Profile
有两种方式可以控制Profiling的开关和级别,
第一种是直接在启动参数中进行设置,如下:
如果想要全局开启Profiling,则可以在mongod启动时加上参数
mongod --profile 1 --slowms 100 # 1表示追踪级别,100表示慢查询判定时间(ms)
若是配置文件中开启的话,配置如下:
operationProfiling:
slowOpThresholdMs: 100
mode: slowOp

第二种是在mongo shell进行实时配置,命令如下:

db.setProfilingLevel(1,200) ---1表示level,200表示慢查询时间(ms),也可以省略时间设置
{ "was" : 1, "slowms" : 100, "ok" : 1 } ---100表示之前的慢查询时间设定值
db.getProfilingStatus() ---查询当前慢查询的状态信息
{ "was" : 1, "slowms" : 200 } ---was后的值表示级别
db.getProfilingLevel() ---只查询Profiling级别可用此命令
1

级别可以取0,1,2 三个值,他们表示的意义如下:
  0 – 不开启
  1 – 记录慢命令 (默认为>100ms)
  2 – 记录所有命令

Mongo Profile慢查询记录直接记录在db中,记录位置是当前开启Profile功能的库下的system.profile集合中,所以只需要直接查询这个集合就行
例:

 查询执行时间大于200ms的Profile记录:
db.system.profile.find( { millis : { $gt : 5 } } )

查看最近的10条记录

db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty()
 查看关于某个collection的相关慢查询操作:
db.system.profile.find({ns:'mydb.table1'}).pretty()
1、查询当前库慢查询的SQL:
db.system.profile.find({millis:{$gt:5000}}).sort({ts:-1}) ---查询时间超过5s的最近SQL
 只显示某些重要指标:

db.system.profile.find({millis:{$gt:1000}},{allUsers:1,client:1,millis:1,nns:1,op:1,query:1,ts:1}).sort({ts:-1})

最近10分钟的慢日志,超过1秒

db.system.profile.aggregate(
[

{$match : {
    millis : { $gt : 1000 } ,
    ts : { $gt : new Date(new Date()-10*60*1000) }
      }
},
{$group : {  _id :{"op":"$op","ns":"$ns"},count: { $sum: 1 }}},
{$sort : {count : -1}}

]
);

show profile命令
此命令查询执行时间超过1ms的最近5条记录

对于Profile的相关信息解释:
op:操作的类型,比如:insert,query,command,remove...
ns:被查询目标的命名空间,一般是数据库名和collection名的组合
query:查询的具体语句,如果是insert操作,则会是insert的语句
command:如果操作是一个command,则command语句记录在此
keysExamined:以前是nscanned,3.2版本之后改为keysExamined,表示执行此次操作所扫描的索引键记录数
updateobj:如果操作是一个update,则update语句记录在此
ndeleted:此次操作删除的文档数
ninserted: 此次操作插入的文档数
nModified:此次操作的update的文档数
writeConflicts:如果一个update语句正在操作一个手游账号购买文档,而另一个update同时进行操作此文档,从而造成的冲突数量
locks:此次操作产生锁的相关信息
nreturned:此次操作返回的文档数
responseLength:操作结果集的大小,
moved:表明本次update是否移动了硬盘上的数据,如果新记录比原记录短,通常不会移动当前记录,如果新记录比原记录长,那么可能会移动记录到其它位置,这时候会导致相关索引的更新.磁盘操作更多,加上索引更新,会使得这样的操作比较慢.(不过这个选在仅针对引擎是MMAPv1)

MongoDB 查询优化

 如果keysExamined (扫描索引建的记录数)远大于nreturned(返回结果的记录数)的话,那么我们就要考虑通过加索引来优化记录定位了。
 responseLength 如果过大,那么说明我们返回的结果集太大了,可能会影响性能,这时请查看find函数的第二个参数是否只写上了你需要的属性名(限制于仅需要查询的字段)。(类似 于MySQL中不要总是select *)
 对于创建索引的建议是:如果很少读,那么尽量不要添加索引,因为索引越多,写操作会越慢。如果读量很大,那么创建索引还是比较划算的。

Profiler 的效率
  Profiling 功能肯定是会影响效率的,但是不太严重,原因是他使用的是system.profile 来记录,而system.profile 是一个capped collection 这种collection 在操作上有一些限制和特点,但是效率更高
也可以对system.profile的size进行设置,具体设置如下:
db.setProfilingLevel()

db.system.profile.drop()

db.createCollection( "system.profile", { capped: true, size:4000000 } )

db.setProfilingLevel(1)

Profile导致的日志骤增异常
异常描述:

设置profile慢查询db.setProfilingLevel(1,0)后, 日志量剧增,导致单个日志文件增大到120G

问题复现:
1.如下的操作默认情况下是不会记录到日志中
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 100 }
shardrs1:PRIMARY> db
testdb
shardrs1:PRIMARY> db.t1.find()
{ "_id" : 1, "a" : 1 }

2.在testdb库开启所有查询都抓取
shardrs1:PRIMARY> db.setProfilingLevel(1,0)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 1, "slowms" : 0 }
注:此时会导致实例下任何库的任何查询都会被记录到日志中

3.分别在不同库下查询
shardrs1:PRIMARY> db
testdb
shardrs1:PRIMARY> db.t1.find()
{ "_id" : 1, "a" : 1 }
执行上述命令后,日志居然会记录下来
2019-06-18T11:39:13.358+0800 I COMMAND [conn2755] command testdb.t1 command: find { find: "t1", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:114 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms
testdb2库下查询时,也会被记录
shardrs1:PRIMARY> use testdb2
switched to db testdb2
shardrs1:PRIMARY> db.t2.find()
{ "_id" : 2, "b" : 2 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 0 }
日志记录如下:
2019-06-18T11:41:11.309+0800 I COMMAND [conn2755] command testdb2.t2 command: find { find: "t2", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:115 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms

4.此时关闭Profile等级为0,但日志中依然会记录上述find信息
shardrs1:PRIMARY> use testdb
switched to db testdb
shardrs1:PRIMARY> db.setProfilingLevel(0)
{ "was" : 1, "slowms" : 0, "ok" : 1 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 0 }

原因分析:
首先我们来看一下db.setProfilingLevel( 1, ,0)的作用
会将当前库下超过0ms的操作记录到system.profile集合中,并写入日志文件中;
mongod也会将其他库中超过0ms的操作写进日志文件中,即使其他库并没有开启profile功能;
官方文档解释:
mongod writes the output of the database profiler to the system.profile collection.
mongod prints information about queries that take longer than the slowOpThresholdMs to the log even when the database profiler is not active.
总结:

故无论profile的模式是什么(0,1,2),只要超时阀值slowOpThresholdMs设定,就会被写入到日志文件中,即使你已经关闭了profile---db.setProfilingLevel(0);

So

一定不要随意将slowOpThresholdMs的值设置为0!
一定不要随意将slowOpThresholdMs的值设置为0!
一定不要随意将slowOpThresholdMs的值设置为0!
相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
1月前
|
存储 Prometheus NoSQL
大数据-44 Redis 慢查询日志 监视器 慢查询测试学习
大数据-44 Redis 慢查询日志 监视器 慢查询测试学习
22 3
|
3月前
|
SQL 关系型数据库 MySQL
【MySQL 慢查询秘籍】慢SQL无处遁形!实战指南:一步步教你揪出数据库性能杀手!
【8月更文挑战第24天】本文以教程形式深入探讨了MySQL慢SQL查询的分析与优化方法。首先介绍了如何配置MySQL以记录执行时间过长的SQL语句。接着,利用内置工具`mysqlslowlog`及第三方工具`pt-query-digest`对慢查询日志进行了详细分析。通过一个具体示例展示了可能导致性能瓶颈的查询,并提出了相应的优化策略,包括添加索引、缩小查询范围、使用`EXPLAIN`分析执行计划等。掌握这些技巧对于提升MySQL数据库性能具有重要意义。
194 1
|
3月前
|
SQL 监控 关系型数据库
"SQL性能瓶颈大揭秘:一步步教你揪出慢查询元凶,从根源解决数据库拖沓问题,让应用速度飞起来!"
【8月更文挑战第31天】作为一名数据库管理员或开发者,面对复杂系统时,运行缓慢的SQL查询常常令人头疼。本文将指导你如何诊断并解决这些问题。首先,通过性能监控工具识别出问题查询;其次,利用`EXPLAIN`分析其执行计划,了解索引使用情况;接着,优化查询语句,如使用合适索引、减少JOIN操作等;再者,优化数据库设计,采用分区表或调整硬件资源;最后,持续监控性能并调优。通过这些步骤,可有效提升数据库的整体性能。
60 0
|
3月前
|
SQL 关系型数据库 MySQL
(十八)MySQL排查篇:该如何定位并解决线上突发的Bug与疑难杂症?
前面《MySQL优化篇》、《SQL优化篇》两章中,聊到了关于数据库性能优化的话题,而本文则再来聊一聊关于MySQL线上排查方面的话题。线上排查、性能优化等内容是面试过程中的“常客”,而对于线上遇到的“疑难杂症”,需要通过理性的思维去分析问题、排查问题、定位问题,最后再着手解决问题,同时,如果解决掉所遇到的问题或瓶颈后,也可以在能力范围之内尝试最优解以及适当考虑拓展性。
182 3
|
6月前
|
SQL 数据库 开发者
百度搜索:蓝易云【SQL高级之慢查询日志?】
慢查询日志是数据库性能优化中一个重要的工具,通过记录执行时间较长的查询语句,帮助识别和解决数据库中的性能问题。它提供了有价值的信息,帮助开发者和管理员优化查询和提升数据库的性能。
69 6
|
6月前
|
关系型数据库 MySQL Shell
百度搜索:蓝易云【Shell脚本实现Mysql持续kill功能】
将以上代码保存为一个名为 `kill_mysql.sh`的文件,并确保该文件具有执行权限(可以使用 `chmod +x kill_mysql.sh`命令赋予执行权限)。然后在终端中运行该脚本即可实现MySQL的持续kill功能。
69 0
|
SQL 缓存 监控
MySQL慢查询:慢SQL定位、日志分析与优化方案,真心不错!
MySQL慢查询:慢SQL定位、日志分析与优化方案,真心不错!
MySQL慢查询:慢SQL定位、日志分析与优化方案,真心不错!
|
SQL 监控 关系型数据库
腾讯一面:你平时怎么排查并调优慢 SQL 的
腾讯一面:你平时怎么排查并调优慢 SQL 的
117 0
|
SQL 监控 关系型数据库
MySQL慢查询日志,让“慢”无所遁形
MySQL慢查询日志,让“慢”无所遁形
257 0
MySQL慢查询日志,让“慢”无所遁形
|
移动开发 应用服务中间件 nginx
没想到,日志还能这么分析!
这次,将用一个大概几万条记录的 nginx 日志文件作为案例,一起来看看如何分析出「用户信息」。
没想到,日志还能这么分析!
下一篇
无影云桌面