Skip to content

Instantly share code, notes, and snippets.

@lemon24

lemon24/debug_storage_timings.py

Created July 9, 2020 12:23
Show Gist options
  • Save lemon24/a0b415a3a6e705143fd1b9b59cb7844d to your computer and use it in GitHub Desktop.
Save lemon24/a0b415a3a6e705143fd1b9b59cb7844d to your computer and use it in GitHub Desktop.
Download ZIP
Raw
debug_storage_timings.py
"""
Extract query timings from (stderr) log output of:
reader --debug-storage [update | update --new-only | search update] --vv
Note that the timings are not entirely accurate:
* for SELECTs, a read lock may be still held after cursor.execute() returns
* we don't know how long transactions take; BEGIN IMMEDIATE tells us how long
it waited for a write lock; BEGIN (DEFERRED) doesn't tell us anything,
since the locks are acquired by a subsequent statement
Nevertheless, we can at least see how much things wait for locks,
and how often they time out.
"""
import json
import sys
import re
from functools import partial
import numpy as np
timings = {}
for line in sys.stdin:
if '"method": ' not in line:
continue
parts = line.split(maxsplit=3)
try:
data = json.loads(parts[3])
except json.JSONDecodeError:
print('---', parts[3])
raise
if not data['method'].startswith('execute'):
continue
filename, name = data['caller']
stmt = data['stmt']
stmt = re.sub('\s+', ' ', stmt).strip()
values = re.escape('(?, ?)')
stmt = re.sub(f'AS \( VALUES {values}(, {values})*', 'AS ( VALUES (?, ?), ...', stmt)
if stmt.startswith('SELECT') and ' FROM ' in stmt:
stmt = stmt.split()
stmt = stmt[:stmt.index('FROM') + 2] + (['...'] if stmt[-2] != 'FROM' else [])
stmt = ' '.join(stmt)
key = (filename, name, stmt, data.get('exception', ''))
timings.setdefault(key, []).append(data['duration'])
funcs = {
'n': len,
'avg': np.mean,
'min': min,
'p50': partial(np.quantile, q=0.5),
'p90': partial(np.quantile, q=0.9),
'p95': partial(np.quantile, q=0.95),
'p99': partial(np.quantile, q=0.99),
'max': max,
}
for (filename, name, stmt, exc), ts in sorted(timings.items()):
print(filename.rpartition('/')[2], name)
short_stmt = ' '.join(stmt.split()[:5])
if short_stmt != stmt and not short_stmt.endswith('...'):
short_stmt += ' ...'
print(short_stmt)
print(exc or '<no exception>')
for fn, f in funcs.items():
print(f" {fn:<3} {f(ts):>10.4f}")
print()
Raw
~output.txt
_search.py _delete_from_search
DELETE FROM entries_search WHERE (_id, ...
<no exception>
n 724.0000
avg 0.3424
min 0.0709
p50 0.0814
p90 0.2752
p95 2.7495
p99 4.2736
max 8.1647
_search.py _delete_from_sync_state
DELETE FROM entries_search_sync_state WHERE (id, ...
<no exception>
n 724.0000
avg 0.0016
min 0.0008
p50 0.0010
p90 0.0011
p95 0.0019
p99 0.0225
max 0.0446
_search.py _insert_into_search_one_chunk
BEGIN IMMEDIATE;
<no exception>
n 17963.0000
avg 0.0051
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 4.9353
_search.py _insert_into_search_one_chunk
BEGIN IMMEDIATE;
sqlite3.OperationalError: database is locked
n 3.0000
avg 5.0086
min 5.0079
p50 5.0085
p90 5.0093
p95 5.0094
p99 5.0095
max 5.0095
_search.py _insert_into_search_one_chunk
DELETE FROM entries_search WHERE (_id, ...
<no exception>
n 15177.0000
avg 0.0358
min 0.0240
p50 0.0282
p90 0.0336
p95 0.0414
p99 0.0510
max 3.1188
_search.py _insert_into_search_one_chunk
INSERT INTO entries_search VALUES ( ...
<no exception>
n 15177.0000
avg 0.0002
min 0.0000
p50 0.0001
p90 0.0004
p95 0.0005
p99 0.0011
max 0.0104
_search.py _insert_into_search_one_chunk
SELECT entries.id, entries.feed, entries.last_updated, coalesce(feeds.user_title, ...
<no exception>
n 817.0000
avg 0.0748
min 0.0015
p50 0.0164
p90 0.1990
p95 0.6119
p99 0.7950
max 1.1776
_search.py _insert_into_search_one_chunk
SELECT last_updated FROM entries ...
<no exception>
n 15177.0000
avg 0.0001
min 0.0000
p50 0.0000
p90 0.0003
p95 0.0006
p99 0.0011
max 0.0072
_search.py _insert_into_search_one_chunk
SELECT to_update FROM entries_search_sync_state ...
<no exception>
n 17963.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0003
max 0.0020
_search.py _insert_into_search_one_chunk
UPDATE entries_search_sync_state SET to_update = ...
<no exception>
n 15177.0000
avg 0.0005
min 0.0000
p50 0.0001
p90 0.0003
p95 0.0005
p99 0.0034
max 0.3050
_sqlite_utils.py ddl_transaction
BEGIN;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0001
_sqlite_utils.py ddl_transaction
COMMIT;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0001
_sqlite_utils.py foreign_keys_off
PRAGMA foreign_keys = OFF;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0001
_sqlite_utils.py foreign_keys_off
PRAGMA foreign_keys = ON;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0149
_sqlite_utils.py foreign_keys_off
PRAGMA foreign_keys;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0001
_sqlite_utils.py get_version
SELECT MAX(version) FROM version;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0001
p95 0.0001
p99 0.0003
max 0.0006
_sqlite_utils.py paginated_query
SELECT entries.feed, feeds.updated, feeds.title, feeds.link, ...
<no exception>
n 16.0000
avg 0.0232
min 0.0048
p50 0.0160
p90 0.0529
p95 0.0818
p99 0.0883
max 0.0899
_sqlite_utils.py paginated_query
SELECT key, value FROM feed_metadata ...
<no exception>
n 9.0000
avg 0.0005
min 0.0000
p50 0.0004
p90 0.0009
p95 0.0014
p99 0.0018
max 0.0019
_sqlite_utils.py paginated_query
SELECT url, updated, http_etag, http_last_modified, ...
<no exception>
n 736.0000
avg 0.0005
min 0.0001
p50 0.0002
p90 0.0013
p95 0.0026
p99 0.0054
max 0.0068
_sqlite_utils.py require_compile_options
PRAGMA compile_options;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0001
max 0.0008
_sqlite_utils.py require_version
SELECT sqlite_version();
<no exception>
n 1460.0000
avg 0.0001
min 0.0000
p50 0.0001
p90 0.0001
p95 0.0001
p99 0.0005
max 0.0129
_sqlite_utils.py setup_db
PRAGMA foreign_keys = ON;
<no exception>
n 1460.0000
avg 0.0000
min 0.0000
p50 0.0000
p90 0.0000
p95 0.0000
p99 0.0000
max 0.0002
_sqlite_utils.py setup_db
PRAGMA journal_mode = WAL;
<no exception>
n 1460.0000
avg 0.0005
min 0.0003
p50 0.0004
p90 0.0006
p95 0.0012
p99 0.0023
max 0.0140
_storage.py _add_or_update_entries
INSERT OR REPLACE INTO entries ...
<no exception>
n 9.0000
avg 1.1368
min 0.0006
p50 0.7391
p90 2.5928
p95 3.1133
p99 3.5298
max 3.6339
_storage.py _get_entries_for_update_one_query
WITH input(feed, id) AS ( ...
<no exception>
n 337.0000
avg 0.0017
min 0.0000
p50 0.0008
p90 0.0020
p95 0.0027
p99 0.0062
max 0.1958
_storage.py _update_feed_full
UPDATE feeds SET title = ...
<no exception>
n 95.0000
avg 0.6430
min 0.0009
p50 0.0023
p90 3.0361
p95 3.5635
p99 3.7989
max 4.1903
_storage.py _update_feed_full
UPDATE feeds SET title = ...
sqlite3.OperationalError: database is locked
n 5.0000
avg 5.0072
min 5.0069
p50 5.0071
p90 5.0074
p95 5.0074
p99 5.0075
max 5.0075
_storage.py _update_feed_last_exception
UPDATE feeds SET last_exception = ...
<no exception>
n 20.0000
avg 0.7590
min 0.0012
p50 0.0078
p90 2.6980
p95 2.8436
p99 2.9984
max 3.0371
_storage.py _update_feed_last_exception
UPDATE feeds SET last_exception = ...
sqlite3.OperationalError: database is locked
n 2.0000
avg 5.0097
min 5.0072
p50 5.0097
p90 5.0117
p95 5.0120
p99 5.0122
max 5.0122
_storage.py _update_feed_last_updated
UPDATE feeds SET last_updated = ...
<no exception>
n 5.0000
avg 0.2866
min 0.0013
p50 0.0018
p90 0.7253
p95 0.7474
p99 0.7652
max 0.7696
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment