Grep a log file for SQL queries and their execution time
I have an application log file that also captures the execution time for each executed SQL statement, like below:-
Sample logs:
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>
...
I want to grep for all these SQL queries along with their execution times, sorted in descending order(based on their execution times).
Desired output:
time: 0.002 | sql: <some_plsql_statement>
time: 0.002 | sql: <some_sql_here>
How can I achieve this with Linux commands? Could someone please help me to achieve this? Thanks in advance.
Extract the relevant fields, printing only lines that match, and sort the result by descending time of execution:
sed -En 's/^.*(time: [0-9.]+) .* (sql: .*)/1 | 2/p' logfile | sort -k2,3nr
Output
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>
Assuming your lines will always have the same number of fields, and that sql: will only appear on the lines you want, you can do this to sort on the 10th field which seems to be the time it took to run the command:
$ 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>
Or, if you want to sort on the 3rd field which I am guessing is the time the command was executed, use:
$ 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>
And if you only want the text from time: to the end of the line, assuming GNU grep, do:
$ 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>