Find the Query Killing Your ERPNext: A MariaDB Slow Query Log Playbook

Karani GeoffreyJuly 20, 20268 min read

Your ERP is slow. Sales is shouting in the WhatsApp group, the accountant cannot open the General Ledger report, and somebody has already suggested "let us upgrade the server". Stop. Before you spend a shilling on more RAM, understand this: in almost every slow ERPNext installation I have opened up, more than 70 percent of total database time is spent inside three to five distinct queries. Not thirty. Three to five. Your job is not to make the database faster. Your job is to find those five queries.

The tool that finds them is the MariaDB slow query log, and most teams have it configured wrong or not at all.

Why the default slow log setup finds nothing

The classic mistake is enabling the slow log with long_query_time = 10, waiting a day, and concluding "there are no slow queries". Of course there are none. A report query that takes 4 seconds and is called 900 times an hour is doing far more damage than a single 12 second cron job, and a 10 second threshold hides it completely.

Total time is what matters, not per-call time. A 0.4 second query executed 50,000 times a day burns more database capacity than a 40 second query executed once.

The second mistake is logging only the SQL text. MariaDB can log the query plan, whether a full scan happened, whether a temporary table spilled to disk. That information turns a guessing game into a diagnosis.

The configuration that actually works

Create a dedicated file so a bench upgrade or a package update never overwrites your work. On Debian and Ubuntu, put it at /etc/mysql/mariadb.conf.d/99-slowlog.cnf.

[mysqld]
slow_query_log                 = 1
slow_query_log_file            = /var/log/mysql/mariadb-slow.log
long_query_time                = 0.3
log_slow_verbosity             = query_plan,explain
log_slow_admin_statements      = 1
log_queries_not_using_indexes  = 0
min_examined_row_limit         = 0
log_output                     = FILE

Notes that will save you an afternoon:

0.3 seconds, not 10. On an ERP, anything above 300ms that runs in a user-facing request is a problem. Start here for a 24 to 48 hour capture, then raise it once the top offenders are fixed.
log_slow_verbosity = query_plan,explain adds the Full_scan, Filesort, Tmp_table_on_disk flags and an inline EXPLAIN to each entry. The accepted values are innodb, query_plan, explain, engine and warnings.
Leave log_queries_not_using_indexes off. On a Frappe site it fires on hundreds of tiny lookups against small tables and drowns your log.
MariaDB 10.11 renamed these variables. slow_query_log became log_slow_query, slow_query_log_file became log_slow_query_file_name, long_query_time became log_slow_query_time, and min_examined_row_limit became log_slow_min_examined_row_limit. The old names still work as aliases, so the block above is safe on 10.6 through 11.x. Confirm with SHOW VARIABLES LIKE '%slow%';.

Create the file and restart:

sudo touch /var/log/mysql/mariadb-slow.log
sudo chown mysql:mysql /var/log/mysql/mariadb-slow.log
sudo systemctl restart mariadb
mariadb -e "SHOW VARIABLES LIKE 'long_query_time'; SHOW VARIABLES LIKE 'slow_query%';"

If you cannot restart production right now

Everything except log_output is dynamic. You can turn the log on live, capture for an hour, and turn it off, with zero downtime:

SET GLOBAL slow_query_log_file = '/var/log/mysql/mariadb-slow.log';
SET GLOBAL long_query_time     = 0.3;
SET GLOBAL log_slow_verbosity  = 'query_plan,explain';
SET GLOBAL slow_query_log      = 1;

-- one hour later
SET GLOBAL slow_query_log = 0;

One catch: long_query_time is read when a session connects. Frappe uses persistent connection pools through gunicorn workers, so existing workers keep the old threshold. Run bench restart (or restart the frappe-bench-web and frappe-bench-workers supervisor groups) after changing it live, otherwise you will capture almost nothing.

What an ERPNext slow log entry actually looks like

Here is a real shape of entry from a wholesale distributor running ERPNext v15. The database name is the Frappe site hash, which is why it looks like line noise.

# Time: 260722 14:32:11
# User@Host: _5f1a2b3c4d5e6f70[_5f1a2b3c4d5e6f70] @ localhost []
# Thread_id: 4412  Schema: _5f1a2b3c4d5e6f70  QC_hit: No
# Query_time: 18.442117  Lock_time: 0.000031  Rows_sent: 50  Rows_examined: 4128744
# Rows_affected: 0  Bytes_sent: 12874
# Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 3  Priority_queue: No
SET timestamp=1784471531;
SELECT `name`, `posting_date`, `account`, `debit`, `credit`, `voucher_no`
FROM `tabGL Entry`
WHERE `company` = 'Kilimani Traders Ltd'
  AND `is_cancelled` = 0
  AND `posting_date` BETWEEN '2025-07-01' AND '2026-06-30'
ORDER BY `posting_date` DESC, `creation` DESC
LIMIT 50;

Read it like a doctor reads a chart:

Rows_sent 50, Rows_examined 4,128,744. A ratio of 82,574 rows read per row returned. Anything above roughly 100 to 1 means the access path is wrong.
Full_scan: Yes. MariaDB read every row in tabGL Entry.
Filesort_on_disk: Yes, Merge_passes: 3. The sort did not fit in sort_buffer_size and spilled to disk three times. On a cheap VPS with network-attached storage, this is where your latency lives.
Lock_time near zero. This is not a locking problem. If Lock_time were large, you would be chasing a different bug entirely.

Do not read the log by hand. Use pt-query-digest

A day of slow log on a busy site is hundreds of megabytes. Percona Toolkit's pt-query-digest normalises queries into fingerprints (literal values replaced by ?), groups them, and ranks them by total time consumed. It works fine against MariaDB logs.

sudo apt-get install -y percona-toolkit
# or, if the distro package is old:
# wget https://downloads.percona.com/downloads/percona-toolkit/LATEST/binary/tarball/...

pt-query-digest /var/log/mysql/mariadb-slow.log > /tmp/digest.txt

Useful flags in practice:

# only the last 6 hours, top 10 queries
pt-query-digest --since '6h' --limit 10 /var/log/mysql/mariadb-slow.log

# rank by rows examined instead of time - finds the index problems
pt-query-digest --order-by Rows_examine:sum --limit 10 /var/log/mysql/mariadb-slow.log

# ignore the background workers, look only at web traffic patterns
pt-query-digest --filter '$event->{fingerprint} !~ m/tabscheduled job log/i' \
  /var/log/mysql/mariadb-slow.log

# tail a live log continuously into a report
pt-query-digest --iterations 0 --run-time 1h /var/log/mysql/mariadb-slow.log

The profile section at the top is the whole point:

# Profile
# Rank Query ID                          Response time    Calls R/Call  V/M
# ==== ================================= ================ ===== ======= =====
#    1 0x3A99CC42AEDCCFCD9E1C1BC0B8E5F9E1 3271.4482 41.8%   177 18.4826  2.31 SELECT tabGL Entry
#    2 0x9F1C7C1E0B4A5D22E1B0A9C7D3E4F001 1544.9013 19.7%  8214  0.1881  0.44 SELECT tabStock Ledger Entry
#    3 0x11B2E9A0C4D3F7889ABC0D1E2F304152  902.3311 11.5%    62 14.5537  6.02 SELECT tabSales Invoice tabSales Invoice Item
#    4 0x7E5D4C3B2A190807F6E5D4C3B2A19080  418.7702  5.3% 41902  0.0100  0.01 SELECT tabSingles
# MISC 0xMISC                             1725.9014 21.7% 66311  0.0260   0.0 <219 ITEMS>

Four queries account for 78 percent of database time. That is your entire work queue for the week.

Reading the per-query block

# Query 1: 0.02 QPS, 0.38x concurrency, ID 0x3A99CC42AEDCCFCD9E1C1BC0B8E5F9E1
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     177
# Exec time     41   3271s      9s     42s     18s     33s      6s     17s
# Rows sent      0   8.64k      50      50      50      50       0      50
# Rows examine  88 692.34M   3.71M   4.22M   3.91M   3.89M  93.24k   3.72M
# Query size     1  84.72k     491     491     491     491       0     491

Two numbers decide your next move. Rows examine 692 million for 8,640 rows returned tells you this is an indexing problem, not a hardware problem. And V/M 2.31 in the profile, the variance-to-mean ratio, says the runtime is unstable, which usually means the plan flips depending on how much of the table is in the buffer pool.

Confirm the diagnosis before you touch anything

Take the fingerprint from the digest, substitute realistic values, and run MariaDB's ANALYZE, which executes the query and shows you estimates next to reality:

ANALYZE SELECT `name`, `posting_date`, `account`, `debit`, `credit`
FROM `tabGL Entry`
WHERE `company` = 'Kilimani Traders Ltd'
  AND `is_cancelled` = 0
  AND `posting_date` BETWEEN '2025-07-01' AND '2026-06-30'
ORDER BY `posting_date` DESC LIMIT 50\G

If r_rows is in the millions and type is ALL, you have confirmed it. Use ANALYZE FORMAT=JSON when you need r_total_time_ms per node to see which join step is the real cost.

Catching the offender in the act

When the ERP freezes right now and you need the culprit in five seconds:

SELECT id, user, time, state, LEFT(info, 160) AS query
FROM information_schema.PROCESSLIST
WHERE command != 'Sleep' AND time > 2
ORDER BY time DESC;

Note the id, capture the SQL, then KILL QUERY <id> to free the site without killing the connection. Then go find that fingerprint in your digest.

Guardrails so the fix does not become the next incident

Rotate the log. A slow log at long_query_time = 0.3 can add gigabytes a day and fill the disk that MariaDB itself lives on. Add a logrotate entry with copytruncate, or use FLUSH SLOW LOGS after moving the file.
Do not use log_slow_rate_limit during diagnosis. It samples one in N slow queries, which makes pt-query-digest totals wrong unless you correct for it. Use it only for permanent low-overhead monitoring.
Watch out for the Frappe scheduler. Long queries from tabScheduled Job Log, tabEmail Queue and repost item valuation jobs will dominate a raw digest. Separate background traffic from user traffic before you prioritise, because a 30 second background job nobody is waiting on is not an emergency.
Leave it on afterwards at 1 second. A permanent 1 second slow log is cheap insurance and gives you a baseline when the next regression ships.

The workflow, compressed

Enable the slow log at 0.3 seconds with query_plan,explain verbosity. Restart bench so workers pick it up.
Capture one full business day, including month-end if you can.
Run pt-query-digest, once by time and once by Rows_examine:sum.
Take the top three fingerprints. Run ANALYZE on each with real parameters.
Fix the access path, usually with a composite index or by removing a wildcard LIKE '%...%' filter in a custom report.
Re-capture and confirm the query left the top ten.

You will spend more time reading than typing, and that is correct. The engineers who fix ERP performance fast are not the ones who know the most tuning parameters. They are the ones who refuse to change anything until the slow log has told them exactly where the time went.

#MariaDB#ERPNext#Performance#Slow Query Log#pt-query-digest