☰

GrepログファイルのSQLクエリと実行時間

tag-icon • tag-icon linux awk sed grep cut
GrepログファイルのSQLクエリと実行時間

次のように実行された各SQL文の実行時間をキャプチャするアプリケーションログファイルがあります。

例ログ：

I 2023-11-15 07:18:00.743Z 1760463 37 ZVRwqItu6aw-b8eejMLI_gAAAAU 1@45077318@A PHP Request Summary: 7 warnings/errors on 6 lines
I 2023-11-15 07:17:15.927Z 1773299 99 ZVRwenUWDwrXl_9NnC-2vwAAAAM 1@45077318@A There is no cache key assigned for the current PID
I 2023-11-15 07:17:55.778Z 1773397 24 ZVRwoydG6PTd3KWR_MnfVAAAABU - Initiating db proxy socket to dev01:8080
I 2023-11-15 07:17:55.865Z 1773397 33 ZVRwoydG6PTd3KWR_MnfVAAAABU 1@45077318@A execStmtEx: time: 0.002 / 0 rows: 1 sql: <some_plsql_statement>
I 2023-11-15 07:17:56.185Z 1773397 65 ZVRwoydG6PTd3KWR_MnfVAAAABU 1@45077318@A applicationConnection TRX Record Commit (execStmtEx) time: 0
I 2023-11-15 07:17:57.515Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.519Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 0 sql: <some_sql_here>
I 2023-11-15 07:17:57.529Z 1755787 27 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.531Z 1755787 27 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 0 <some_sql_here>
I 2023-11-15 07:17:57.535Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.542Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
...

私はこれらすべてのSQLクエリと実行時間を降順（実行時間に基づいて）で並べ替えて見つけるためにgrepを使用したいと思います。

希望の出力：

time: 0.002 | sql: <some_plsql_statement>
time: 0.002 | sql: <some_sql_here>

Linuxコマンドを使用してこれをどのように達成できますか？誰でも私がこれを達成するのを助けることができますか？よろしくお願いします。

答え1

関連フィールドを抽出し、一致する行のみを印刷し、実行時間に基づいて降順に結果をソートします。

sed -En 's/^.*(time: [0-9.]+) .* (sql: .*)/\1 | \2/p' logfile | sort -k2,3nr

出力

time: 0.002 | sql: <some_plsql_statement>
time: 0.002 | sql: <some_sql_here>
time: 0.002 | sql: <some_sql_here>
time: 0.002 | sql: <some_sql_here>
time: 0.001 | sql: <some_sql_here>
time: 0.001 | sql: <some_sql_here>

答え2

行に常に同じ数のフィールドがあり、目的の行にのみ表示されると仮定すると、これをsql:実行して10番目のフィールドで並べ替えることができます。これはコマンドの実行にかかる時間のようです。

$ grep sql: log | sort -rnk 10,10
I 2023-11-15 07:17:57.542Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.535Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.529Z 1755787 27 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:55.865Z 1773397 33 ZVRwoydG6PTd3KWR_MnfVAAAABU 1@45077318@A execStmtEx: time: 0.002 / 0 rows: 1 sql: <some_plsql_statement>
I 2023-11-15 07:17:57.519Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 0 sql: <some_sql_here>
I 2023-11-15 07:17:57.515Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 1 sql: <some_sql_here>

または、3番目のフィールド（コマンドの実行時間のようです）に基づいて並べ替えるには、次のようにします。

$ grep sql: log | sort -rnk 3,3
I 2023-11-15 07:17:57.542Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.535Z 1755787 28 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.529Z 1755787 27 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.002 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:57.519Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 0 sql: <some_sql_here>
I 2023-11-15 07:17:57.515Z 1755787 26 ZVRwpA5grkn1knR4gk6FMwAAABA 1@45077318@A queryResults: time: 0.001 / 0 rows: 1 sql: <some_sql_here>
I 2023-11-15 07:17:55.865Z 1773397 33 ZVRwoydG6PTd3KWR_MnfVAAAABU 1@45077318@A execStmtEx: time: 0.002 / 0 rows: 1 sql: <some_plsql_statement>

time:GNU 仮定の下で行末までのテキストのみを希望する場合は、grep次のようにします。

$ grep -o 'time:.* sql:.*' log | sort -rnk 2,2
time: 0.002 / 0 rows: 1 sql: <some_sql_here>
time: 0.002 / 0 rows: 1 sql: <some_sql_here>
time: 0.002 / 0 rows: 1 sql: <some_sql_here>
time: 0.002 / 0 rows: 1 sql: <some_plsql_statement>
time: 0.001 / 0 rows: 1 sql: <some_sql_here>
time: 0.001 / 0 rows: 0 sql: <some_sql_here>

関連情報