Sunday, June 13, 2021

The new dashboard in Jane is still slow, and if often goes into “502 Bad Gateway” mode. This time I triggered 502 by deleting a ticket.

I consult Analyzing RAM usage and then compare Jane with another production site that is not slow.

Output of ps -e -orss=,args= |awk ‘{print $1 ” ” $2 }’| awk ‘{tot[$2]+=$1;count[$2]++} END {for (i in tot) {print tot[i],i,count[i]}}’ | sort -n

On Jane:

...
22784 postgres: 6
24336 /usr/lib/libreoffice/program/soffice.bin 1
29204 smtpd 3
37668 /lib/systemd/systemd-journald 1
114352 /usr/sbin/mysqld 1
130680 python 1
964544 /usr/bin/uwsgi 7

On the other production site:

...
71908 /usr/lib/libreoffice/program/soffice.bin 1
121340 /usr/sbin/mysqld 1
136868 python 1
1289172 /usr/bin/uwsgi 11

Output of top (and then M) on Jane:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
26071 www-data  20   0  342784 149880   5144 S   0,0   7,5   1:07.29 uwsgi
26070 www-data  20   0  339304 145692   4488 S   0,0   7,3   1:41.30 uwsgi
26109 www-data  20   0  332804 138796   3872 S   0,0   7,0   0:00.46 uwsgi
25598 www-data  20   0  330812 137752   4820 S   0,0   6,9   0:15.93 uwsgi
26110 www-data  20   0  329576 135692   3872 S   0,0   6,8   0:00.56 uwsgi
25593 www-data  20   0  327696 134952   5000 S   0,0   6,8   0:16.70 uwsgi
32482 www-data  20   0  284960 130680   7872 S   0,0   6,6   0:29.15 python
25596 www-data  20   0  315052 121780   4868 S   0,0   6,1   0:11.89 uwsgi
25283 mysql     20   0 1727408 114352   1960 S   0,0   5,7   2:34.27 mysqld
...

Nothing suspicious there.

But here. The /var/log/mysql/error.log says:

2021-06-13  2:58:27 613 [Warning] Aborted connection 613 to db: 'xyz' user:
'abcd' host: 'cdef' (Got timeout reading communication packets)

Whenever a communication error occurs, MySQL increments the status counter for either Aborted_clients or Aborted_connects. Muhammad Irfan

My feeling says that we can exclude Aborted_connects (failed attempts to connect to the MySQL server), so this log entry informs about a case of Aborted_clients, IOW a connection that was aborted because the client died without closing the connection properly.

The client died without closing the connection properly?

Irfan: “To be honest, aborted connection errors are not easy to diagnose.”

I should now enable the general query log of the MySQL server

https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_general_log

https://dev.mysql.com/doc/refman/5.6/en/query-log.html

As it seems I can activate the general MySQL query log simply by adding a SET to the OPTIONS of my DATABASES setting.

Something like this:

DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.mysql',
        ...
        'OPTIONS': {
           "init_command": "SET default_storage_engine=MyISAM; SET log_output=FILE; SET general_log=ON; SET general_log_file=xyz-general.log"
        }
}

   "init_command": "SET default_storage_engine=MyISAM;
   SET log_output=FILE;
   SET general_log=ON;
   SET general_log_file=jane-general.log"

If you specify no name for the general query log file, the default name is host_name.log. The server creates the file in the data directory unless an absolute path name is given to specify a different directory.

What is the “data directory” in MySQL?

https://dev.mysql.com/doc/refman/5.7/en/data-directory.html

Short answer: For a database named “xyz” it is /var/lib/mysql/xyz.

So after restarting Lino, my log file should be in /var/lib/mysql/xyz/xyz-general.log

Only problem is that it doesn’t work. After almost an hour of trying, I still didn’t manage to activate the MySQL general query log (at runtime, i.e. without changing the server config).

The /etc/mysql/mariadb.conf.d/50-server.cnf config file says this:

# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
# As of 5.1 you can enable the log at runtime!
#general_log_file       = /var/log/mysql/mysql.log
#general_log            = 1

So I finally uncommented these two lines in the /etc/mysql/mariadb.conf.d/50-server.cnf and said sudo service mysql restart.

Now I have a /var/log/mysql/mysql.log file.

Every ten seconds it says:

210613 19:55:12          467 Query    SELECT COUNT(*) AS `__count` FROM `notify_message` LEFT OUTER JOIN `users_user` ON (`notify_message`.`user_id` = `users_user`.`id`) WHERE (`notify_message`.`sent` IS NULL AND NOT (`users_user`.`email` = '' AND `users_user`.`email` IS NOT NULL) AND `notify_message`.`mail_mode` = 'often')
210613 19:55:14          467 Query    SELECT `django_mailbox_mailbox`.`id`, `django_mailbox_mailbox`.`name`, `django_mailbox_mailbox`.`uri`, `django_mailbox_mailbox`.`from_email`, `django_mailbox_mailbox`.`active`, `django_mailbox_mailbox`.`last_polling` FROM `django_mailbox_mailbox` WHERE `django_mailbox_mailbox`.`active`
                       467 Query      UPDATE `django_mailbox_mailbox` SET `last_polling` = '2021-06-13 17:55:14.871730' WHERE `django_mailbox_mailbox`.`id` = 1
210613 19:55:22          467 Query    SELECT COUNT(*) AS `__count` FROM `notify_message` LEFT OUTER JOIN `users_user` ON (`notify_message`.`user_id` = `users_user`.`id`) WHERE (`notify_message`.`sent` IS NULL AND NOT (`users_user`.`email` = '' AND `users_user`.`email` IS NOT NULL) AND `notify_message`.`mail_mode` = 'often')
210613 19:55:24          467 Query    SELECT `django_mailbox_mailbox`.`id`, `django_mailbox_mailbox`.`name`, `django_mailbox_mailbox`.`uri`, `django_mailbox_mailbox`.`from_email`, `django_mailbox_mailbox`.`active`, `django_mailbox_mailbox`.`last_polling` FROM `django_mailbox_mailbox` WHERE `django_mailbox_mailbox`.`active`
                             467 Query        UPDATE `django_mailbox_mailbox` SET `last_polling` = '2021-06-13 17:55:24.889516' WHERE `django_mailbox_mailbox`.`id` = 1

Yes, okay, that’s how to have MySQL log everything. But it’s not useful for our problem. Because people are working on other Lino sites on the same server.

I will rather try Exploring SQL activity in Lino Noi.