2

一部のログでは、percona ツールキットの pt-query-digest ツールが正常に機能しているように見えますが、他のログでは次の出力が得られます。

# Files: /.../mysqld_slow.log
# Overall: 0 total, 1 unique, 0 QPS, 0x concurrency ______________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Query size        18.19M  18.19M  18.19M  18.19M  18.19M       0  18.19M

# Profile
# Rank       Query ID   Response time Calls      R/Call     Apdx V/M   Ite
# ========== ========== ========== ========== ========== ==== ===== ======
$

ログファイルの何が問題なのか知っている人はいますか? 次の最初の 10 行を持つ有効なようです。

Sep 28 00:00:37 gcdb-master mysqld_slow_log: SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 576 LIMIT 1;
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # Query_time: 0.041188  Lock_time: 0.000046 Rows_sent: 1  Rows_examined: 46418
Sep 28 00:00:37 gcdb-master mysqld_slow_log: SET timestamp=1348790434;
Sep 28 00:00:37 gcdb-master mysqld_slow_log: SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 286358 LIMIT 1;
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # Query_time: 0.030769  Lock_time: 0.000050 Rows_sent: 1  Rows_examined: 46583
Sep 28 00:00:37 gcdb-master mysqld_slow_log: SET timestamp=1348790434;
Sep 28 00:00:37 gcdb-master mysqld_slow_log: SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 286679 LIMIT 1;
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
Sep 28 00:00:37 gcdb-master mysqld_slow_log: # Query_time: 0.594351  Lock_time: 0.000038 Rows_sent: 12  Rows_examined: 342673
4

2 に答える 2

4

サンプル出力でいくつかのテストを実行しましたが、ファイルが無効であると思われます。このファイルは、各行の syslog のような部分を切り取って取得し、最初のクエリの前に 2 つの欠落している #description-lines を追加して、機能しているように見えます

# User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
# Query_time: 0.041188  Lock_time: 0.000046 Rows_sent: 1  Rows_examined: 46418
SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 576 LIMIT 1;
# User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
# Query_time: 0.041188  Lock_time: 0.000046 Rows_sent: 1  Rows_examined: 46418
SET timestamp=1348790434;
SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 286358 LIMIT 1;
# User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
# Query_time: 0.030769  Lock_time: 0.000050 Rows_sent: 1  Rows_examined: 46583
SET timestamp=1348790434;
SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 286679 LIMIT 1;
# User@Host: db_one[db_one] @ ip-127.0.0.1.ec2.internal [127.0.0.1]
# Query_time: 0.594351  Lock_time: 0.000038 Rows_sent: 12  Rows_examined: 342673

#description 行で始まるように最初の行を削除した同じファイルと同様に、次のように出力します。

# 240ms user time, 20ms system time, 24.59M rss, 87.74M vsz
# Current date: Fri Nov  2 22:03:02 2012
# Hostname: mintaka
# Files: orig.log
# Overall: 3 total, 1 unique, 0 QPS, 0x concurrency ______________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          113ms    31ms    41ms    38ms    40ms     5ms    40ms
# Lock time          142us    46us    50us    47us    49us     2us    44us
# Rows sent              3       1       1       1       1       0       1
# Rows examine     136.15k  45.33k  45.49k  45.38k  44.45k    0.00  44.45k
# Query size           234      76      79      78   76.28    1.50   76.28

# Profile
# Rank Query ID           Response time Calls R/Call Apdx V/M   Item
# ==== ================== ============= ===== ====== ==== ===== ==========
#    1 0x0C756AF10BC44B0D 0.1131 100.0%     3 0.0377 1.00  0.00 SELECT companies

# Query 1: 0 QPS, 0x concurrency, ID 0x0C756AF10BC44B0D at byte 226 ______
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: |    ^   |
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count        100       3
# Exec time    100   113ms    31ms    41ms    38ms    40ms     5ms    40ms
# Lock time    100   142us    46us    50us    47us    49us     2us    44us
# Rows sent    100       3       1       1       1       1       0       1
# Rows examine 100 136.15k  45.33k  45.49k  45.38k  44.45k    0.00  44.45k
# Query size   100     234      76      79      78   76.28    1.50   76.28
# String:
# Hosts        ip-127.0.0.1.ec2.internal
# Users        db_one
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'companies'\G
#    SHOW CREATE TABLE `companies`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT  `companies`.* FROM `companies`  WHERE `companies`.`id` = 286358 LIMIT 1\G

したがって、問題はログ ファイルの形式とおそらくローテーションに関連していると思います(たとえば、ファイルが切り詰められて最初の #description が失われます)。

また、Percona ユーティリティ コードについても少し調べました。デフォルトのパーサー (slowlog) は #Time 行を検索してタイムスタンプを取得します。これは私のスローログで見つけましたが、あなたのものにはありません。これは読み取り自体には影響しませんが、結果をゆがめる可能性があります。

";\n#"また、入力レコード区切りとしても使用するため、syslog 形式はデフォルトの--type slowlogの明確な「いいえ」です。他のものも、syslog+slowlog 形式では機能しないようです。

入力レコード区切りを変更し、ハックを追加して各行の syslog 部分を削除しようとしましたが、結果は機能しているように見えますが、既知のスローログの結果が一貫していないため、機能しないのではないかと心配しています。

残念ながら、最も簡単な方法は、ファイルの先頭を切り取り、次に各行の先頭を切り捨ててから、ユーティリティに渡すことです。

sed -e '/.*: #/,$b' -e 'd' < slow.log \
| cut -d' ' -f6- \
| pt-query-digest -
于 2012-11-02T21:07:10.270 に答える
0

ツールがそのような出力を持つべきではないように思われるので、バグレポートを提出することを検討するかもしれません。

エラーはログファイルにある場合とない場合があります。ログファイルをいくつかの小さなファイルに分割して、ファイルを解析できるかどうかを確認してみてください。これにより、少なくともバグの原因を絞り込むことができます。小さいファイルがすべて正しく解析されている場合は、リソースが不足しているか、リソースを大量に使用しているために強制終了されていることに関連している可能性がありpt-query-digestます。

于 2012-10-30T18:40:19.267 に答える