This post appeared originally in our sysadvent series and has been moved here following the discontinuation of the sysadvent microsite
So, the database is slow - why?
There can be several reasons for this. Perhaps a few very heavy queries are bogging down the database. In this case, you’d typically set up slow query logging and find them in the slow.log. However, sometimes the reason is simply lots of frequent queries.
The simple query is run twice a second and completed in 30ms during the beta testing. However, the database has grown and the query contains clauses not catched by indexes you set up initially, so by now it takes more than 0.5s to run. It may be possible to catch it in the slow-query log by tuning down the threshold for what queries to run, but quite often one doesn’t want to log every query (due to IO-performance and disk usage) and analyzing the log file can be non-trivial when there are gigabytes of it
Enter snapshot logging. Simply capture the process list in a regular interval i.e. twice a minute; now it’s easy to do statistics on what queries the database is most busy with - it’s just a matter of counting the number of times we see the different queries!
MariaDB/MySQL/Percona
I usually throw this into the crontab:
* * * * * { for i in 1 2 ; do sleep $((RANDOM/1092)) ; date --rfc-3339=seconds; mysql -e "show processlist" ; done ; } >> /var/log/mysql-processlist.log 2>&1
The random sleep is to avoid biases due to the monitoring always running exactly before or during cronjobs that accesses the database.
Log rotation is nice to have - this can be thrown into the logrotate configuration:
/var/log/mysql-processlist.log {
create 640 mysql adm
rotate 30
daily
compress
dateext
dateformat -%Y-%m-%d
}
And to analyze the data - usually something like this:
cat /var/log/mysql-processlist.log | \
grep -v Sleep | \
grep -vE '^\| Id.*User.*Host' | \
grep -v 'show processlist' | \
grep -vE '^20[12][0-9]-[01]' | \
cut -f8 | \
perl -pe 's/\'"'"'.*?(\'"'"'|$)/'"'"'asdf'"'"'/; s/201[0-9]-\d\d-\d\d/YYYY-xx-xx/g; s/\d{3,10}/XXX/g; s/ = \d+/ = XXX/g' | \
sort | \
uniq -c | \
sort -nr | less
If the list is relatively short, probably the queries at the top should be investigated closer. If it has a long tail, probably the Perl regexps at the top should be fixed up better to group up similar queries.
Postgres
To get snapshot logging in postgres, we’ll need to set the
track_activites
boolean configuration parameter on.
track_activity_query_size
can also be tuned upwards.
Postgres is sweet, the process list is available in true database format. Why log to a log file when one can log it to a database table? If one knows a bit of SQL, it’s much easier to do analysis on data in a database than on a log file.
Set it up like this:
$ sudo -u postgres psql
postgres=# create database meta_pg_monitoring;
postgres=# \c meta_pg_monitoring;
meta_pg_monitoring=# select now(),* into pg_stat_activity_log from pg_stat_activity;
Then, going forward, use some crontab entry like this (as postgres user):
* * * * * { for i in 1 2 ; do sleep $((RANDOM/1092)) ; psql -c 'insert into pg_stat_activity_log select now(),* from pg_stat_activity;' meta_pg_monitoring > /dev/null 2>&1 ; done ; } >> /var/log/mysql-processlist.log 2>&1
Simple statistics:
meta_pg_monitoring=# select count(*),current_query from pg_stat_activity_log where not waiting group by current_query order by count(*);
You’d probably want to tune this by using regexps (the substring function) on the current_query, restricting the now-timestamp, adding some indexes and what-not. Partial indexes is allowed in postgres:
meta_pg_monitoring=# create index pg_stat_activity_log_nonwaiting on pg_stat_activity_log(now) where not waiting;
cleanup job:
10 * * * * psql -c delete from pg_stat_activity_log where now+'2 days'<now();
Note: look out for long-lasting transactions! If now()-xact_start is high on a connection, the transaction was started but never completed (with commit or rollback), this may cause a big performance drop!
Apache
We usually log elapse time in the access log, hence the snapshots aren’t that important for us. Still they may be useful, i.e. if the request never gets completed they won’t be logged in the access log.
Snapshots can be created by enabling the server-status server module. The snapshot will come in HTML-format, which is not so handy to work with.
* * * * * sleep $((RANDOM/512)) ; wget -qO /var/log/apache//server-status/$(date +\%s).html http://localhost/server-status
Since this creates one file for each snapshot, ordinary log rotation cannot be used … but this one ought to do the trick (adjust according to where your Apache log files are):
0 0 * * * cd /var/log/apache/ ; mv server-status server-status.$(date +\%F) ; mkdir server-status ; tar cjf server-status.$(date +\%F).tar.bz2 --remove-files server-status.$(date +\%F) ; find /var/log/apache/ -name 'server-status*tar.bz2' -mtime +5 -delete ;
System process list
I’d very much recommend installing atop, though by default it logs every tenth minute - that’s far too seldom when researching performance troubles, the servers may be totally clogged down for a whole minute and idle for nine minutes, and atop will show 10% resource utilization.
Experiences, summarized
There are two classes of troubles where the snapshot logging can be extremely useful, it’s for finding the culprit of performance problems, and it’s for doing post-incident investigations.
When it comes to performance problems, if you log all the requests (which one typically does with the web server) and have all the important statistics (particularly timing statistics) available there, then it’s not so much need for snapshot logging. However, if the complete log is huge, analyzing the snapshot logs may be a lot faster and a lot easier than analyzing the full logs.
As for incidents where the service has become unavailable or severely degraded, the cause may be found in requests that never finished, and those may not be found in the request log, hence snapshot logging can be useful for seeing exactly what the server was working with at the moment things went wrong.
In my experience, atop and snapshots of the database process list has in many cases been extremely useful, while I very seldom look into the snapshot logging of the web server process lists.
The irony of insecure security software
It can probably be understood from my previous blog post that if it was up to me, I’d avoid products like CrowdStrike - but every now and then I still have to install something like that. It’s not the idea of “security software” per se that I’m against, it’s the actual implementation of many of those products. This post lists up some properties that should be fulfilled for me to happy to install such a product.