how to test API request speed?

ornanovitch

Hey there!

My forum experiences some slow-down on pages load since several weeks (only on XHR GET requests). We have a self-hosted server and we know very well its specs. I already began to investigate on the engines side (php-fpm, mariaDB, nginx) but nothing relevant for the moment, although I suspect mysql to be the culprint.

The only aspect I don't really master is the Flarum API requests themselves, which have a really bad response time (>1000ms). So I'd like to figure out how to test those requests directly within our VM, to verify if it's totally a backend problem or not.

For example, how could I benchmark something like GET localhost/api/discussions/346-blablabla?bySlug=true&page[near]=9 in a CLI way?

Thanks!

Flarum core 1.1.1
PHP version: 7.3.31-1~deb10u1
MySQL version: 5.5.5-10.3.31-MariaDB-0+deb10u1
Loaded extensions: Core, date, libxml, openssl, pcre, zlib, filter, hash, pcntl, Reflection, SPL, sodium, session, standard, mysqlnd, PDO, xml, calendar, ctype, curl, dom, mbstring, fileinfo, ftp, gd, gettext, gmp, iconv, json, ldap, exif, mysqli, pdo_mysql, Phar, posix, readline, shmop, SimpleXML, sockets, sysvmsg, sysvsem, sysvshm, tokenizer, wddx, xmlreader, xmlwriter, xsl, zip, Zend OPcache
+-------------------------------+---------+--------+
| Flarum Extensions             |         |        |
+-------------------------------+---------+--------+
| ID                            | Version | Commit |
+-------------------------------+---------+--------+
| flarum-tags                   | v1.1.0  |        |
| flarum-markdown               | v1.1.0  |        |
| the-turk-flamoji              | 1.0.2   |        |
| kyrne-websocket               | 3.3.0   |        |
| fof-user-directory            | 1.1.0   |        |
| fof-user-bio                  | 1.0.1   |        |
| fof-upload                    | 1.0.7   |        |
| fof-terms                     | 1.1.2   |        |
| fof-split                     | 1.0.1   |        |
| fof-reactions                 | 1.0.2   |        |
| fof-nightmode                 | 1.1.1   |        |
| fof-merge-discussions         | 1.0.0   |        |
| fof-links                     | 1.0.3   |        |
| fof-linguist                  | 1.0.3   |        |
| fof-formatting                | 1.0.2   |        |
| fof-drafts                    | 1.0.3   |        |
| fof-doorman                   | 1.0.1   |        |
| fof-byobu                     | 1.0.2   |        |
| flarum-subscriptions          | v1.1.0  |        |
| flarum-sticky                 | v1.1.0  |        |
| flarum-statistics             | v1.1.0  |        |
| flarum-nicknames              | v1.1.0  |        |
| flarum-mentions               | v1.1.3  |        |
| flarum-lock                   | v1.1.0  |        |
| flarum-lang-french            | v3.3.0  |        |
| flarum-lang-english           | v1.1.0  |        |
| flarum-emoji                  | v1.1.1  |        |
| clarkwinkelmann-circle-groups | 1.0.0   |        |
| askvortsov-saml               | v2.4.0  |        |
| askvortsov-rich-text          | v2.1.0  |        |
| askvortsov-markdown-tables    | v1.2.1  |        |
| askvortsov-checklist          | v1.3.1  |        |
+-------------------------------+---------+--------+
Base URL: https://<private>
Installation path: /var/www/flarum
Queue driver: redis
Mail driver: smtp
Debug mode: off

luceos

ornanovitch you can create an API master token to authenticate and then run requests with that, eg with postman.

ornanovitch

Thanks! I think I made it with cURL:

curl -v 'localhost/api/discussions/159-<a simple discussion with less than 10 posts>?bySlug=true&page%5Bnear%5D=12' \ -H 'Accept-Encoding: gzip, deflate, br' \ -H 'Referer: localhost/d/<the discussion>/12' \ -H 'X-CSRF-Token: [...]' \ -H 'Cookie: flarum_remember=[...]; flarum_session=[...]' \ -w %{time_connect}:%{time_starttransfer}:%{time_total}

Directly within the VM, it took 7 seconds to get the response... I guess something's definitely wrong.

luceos

ornanovitch that sounds like an issue, does MySQL slow query log show anything?

And please post the output of php flarum info.

ornanovitch

luceos I updated the OP with our flarum info. I already tried to disable some extensions that I suspected (kyrne-websocket, fof-reactions, askvortsov-rich-text) but with no luck.

does MySQL slow query log show anything?

First time I looked there was nothing but it was set to 10s. I just set it to 3s and here we go! It's weird, it seems that any little query is affected...

/usr/sbin/mysqld, Version: 10.3.31-MariaDB-0+deb10u1 (Debian 10). started with:
Tcp port: 3306  Unix socket: /run/mysqld/mysqld.sock
Time		    Id Command	Argument

# Time: 220117 14:34:15
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8828  Schema: flarum  QC_hit: No
# Query_time: 3.097120  Lock_time: 0.000039  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
use flarum;
SET timestamp=1642426455;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:34:12', `last_ip_address` = '127.0.0.1', `last_user_agent` = 'curl/7.64.0' where `id` = 610;

# Time: 220117 14:34:20
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8828  Schema: flarum  QC_hit: No
# Query_time: 4.324685  Lock_time: 0.000029  Rows_sent: 12  Rows_examined: 12
# Rows_affected: 0  Bytes_sent: 1005
SET timestamp=1642426460;
select * from `flarumpost_reactions` where `reaction_id` is not null and `flarumpost_reactions`.`post_id` in (910, 915, 935, 1125, 1156, 1627, 1630, 1644, 1647, 2530, 2554);

# Time: 220117 14:37:15
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8838  Schema: flarum  QC_hit: No
# Query_time: 3.387412  Lock_time: 0.000053  Rows_sent: 1  Rows_examined: 1
# Rows_affected: 0  Bytes_sent: 984
SET timestamp=1642426635;
select * from `flarumaccess_tokens` where ((`type` = 'developer') or (`type` = 'session_remember' and `last_activity_at` > '2017-01-18 13:37:12') or (`type` = 'session' and `last_activity_at` > '2022-01-17 12:37:12')) and `token` = '[...]' limit 1;

# Time: 220117 14:37:17
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8836  Schema: flarum  QC_hit: No
# Query_time: 3.005733  Lock_time: 0.000048  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426637;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:37:14', `last_ip_address` = '192.168.10.100', `last_user_agent` = 'Mozilla/5.0 (X11; Linux x86_64; rv:96.0) Gecko/20100101 Firefox/96.0' where `id` = 610;

# Time: 220117 14:37:21
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8838  Schema: flarum  QC_hit: No
# Query_time: 3.215694  Lock_time: 0.000065  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426641;
update `flarumusers` set `last_seen_at` = '2022-01-17 13:37:18' where `id` = 2;

# Time: 220117 14:37:28
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8839  Schema: flarum  QC_hit: No
# Query_time: 3.923465  Lock_time: 0.000055  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426648;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:37:24', `last_ip_address` = NULL, `last_user_agent` = NULL where `id` = 610;

# Time: 220117 14:37:33
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8839  Schema: flarum  QC_hit: No
# Query_time: 5.192325  Lock_time: 0.000140  Rows_sent: 1  Rows_examined: 1
# Rows_affected: 0  Bytes_sent: 900
SET timestamp=1642426653;
select * from `flarumaccess_tokens` where ((`type` = 'developer') or (`type` = 'session_remember' and `last_activity_at` > '2017-01-18 13:37:28') or (`type` = 'session' and `last_activity_at` > '2022-01-17 12:37:28')) and `token` = '[...]' limit 1;

# Time: 220117 14:37:36
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8840  Schema: flarum  QC_hit: No
# Query_time: 5.317106  Lock_time: 0.000059  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426656;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:37:30', `last_ip_address` = '192.168.10.100', `last_user_agent` = 'Mozilla/5.0 (X11; Linux x86_64; rv:96.0) Gecko/20100101 Firefox/96.0' where `id` = 610;

# Time: 220117 14:37:40
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8840  Schema: flarum  QC_hit: No
# Query_time: 4.129018  Lock_time: 0.000020  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426660;
update `flarumdiscussion_user` set `last_read_at` = '2022-01-17 13:37:36', `last_read_post_number` = 4 where `discussion_id` = 373 and `user_id` = 2;

# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8839  Schema: flarum  QC_hit: No
# Query_time: 6.483146  Lock_time: 0.000207  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426660;
update `flarumusers` set `last_seen_at` = '2022-01-17 13:37:33' where `id` = 2;

# Time: 220117 14:38:04
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8842  Schema: flarum  QC_hit: No
# Query_time: 3.404720  Lock_time: 0.000038  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426684;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:38:00', `last_ip_address` = '192.168.10.100', `last_user_agent` = 'Mozilla/5.0 (X11; Linux x86_64; rv:96.0) Gecko/20100101 Firefox/96.0' where `id` = 610;

# Time: 220117 14:38:39
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8852  Schema: flarum  QC_hit: No
# Query_time: 3.349745  Lock_time: 0.000045  Rows_sent: 1  Rows_examined: 1
# Rows_affected: 0  Bytes_sent: 984
SET timestamp=1642426719;
select * from `flarumaccess_tokens` where ((`type` = 'developer') or (`type` = 'session_remember' and `last_activity_at` > '2017-01-18 13:38:36') or (`type` = 'session' and `last_activity_at` > '2022-01-17 12:38:36')) and `token` = '[...]' limit 1;

# Time: 220117 14:38:47
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8853  Schema: flarum  QC_hit: No
# Query_time: 4.812028  Lock_time: 0.000103  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426727;
update `flarumusers` set `last_seen_at` = '2022-01-17 13:38:42' where `id` = 2;

# Time: 220117 14:38:50
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8853  Schema: flarum  QC_hit: No
# Query_time: 3.522467  Lock_time: 0.000049  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1642426730;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:38:47', `last_ip_address` = '192.168.10.100', `last_user_agent` = 'Mozilla/5.0 (X11; Linux x86_64; rv:96.0) Gecko/20100101 Firefox/96.0' where `id` = 610;

wolfman

Especially those select-queries should not take this amount of time.

Do you have enough free RAM?
Have you overcommitted RAM to MySQL?
Is the system swapping?
Have you checked if you have a faulty disk or raid?

ornanovitch

wolfman thx for your answer

Do you have enough free RAM?

yes:

> # free -h
              total        used        free      shared  buff/cache   available
Mem:          4.0Gi       510Mi       3.4Gi        49Mi       141Mi       3.5Gi
Swap:            0B          0B          0B

Have you overcommitted RAM to MySQL?

I double-checked, everything looks good and InnoDB is happy

Is the system swapping?

Nope, see above

Have you checked if you have a faulty disk or raid?

Yes, it's fine, especially since we changed all our disks several months ago (our server is managed with Proxmox & ZFS)

When I test one of the slow-query (e.g. select * from 'flarumpost_reactions' where 'reaction_id' is not null and 'flarumpost_reactions'.'post_id' in (910, 915, 935, 1125, 1156, 1627, 1630, 1644, 1647, 2530, 2554);) directly onto the mysql cli, I got the response in 0.002 sec (vs. 4.324685 sec in the above report) 🤔

edit: please note that our forum is little (50 users, 2000 posts...) although it has some complexity around tag permissions

ornanovitch

⚠️ caught red-handed! I tried multiple time to manually update my last-seen-at value. 9 times out of 10 it happened in less than 1 sec. But one time:

MariaDB [flarum]> update `flarumusers` set `last_seen_at` = '2022-01-17 16:43:59' where `id` = 2;
Query OK, 1 row affected (3.775 sec)
Rows matched: 1  Changed: 1  Warnings: 0

3.775 sec...

ornanovitch

Some investigation progress:

MariaDB [flarum]> update `flarumusers` set `last_seen_at` = '2022-01-17 16:43:12' where `id` = 2;
Query OK, 1 row affected (2.028 sec)
Rows matched: 1  Changed: 1  Warnings: 0

MariaDB [flarum]> SHOW PROFILE;
+------------------------+----------+
| Status                 | Duration |
+------------------------+----------+
| Starting               | 0.000074 |
| Checking permissions   | 0.000009 |
| Opening tables         | 0.000156 |
| After opening tables   | 0.000012 |
| System lock            | 0.000006 |
| Table lock             | 0.000007 |
| Init for update        | 0.000074 |
| Updating               | 0.000134 |
| End of update loop     | 0.000010 |
| Query end              | 0.000005 |
| Commit                 | 2.026614 | <<< HERE
| Closing tables         | 0.000050 |
| Unlocking tables       | 0.000016 |
| Closing tables         | 0.000116 |
| Starting cleanup       | 0.000015 |
| Freeing items          | 0.000015 |
| Updating status        | 0.000060 |
| Reset for next command | 0.000030 |
+------------------------+----------+
18 rows in set (0.001 sec)

wolfman

Can you try running MySQLTuner https://github.com/major/MySQLTuner-perl

wget -O mysqltuner.pl http://mysqltuner.pl
perl mysqltuner.pl

Edit: And can you check the output for creating this 2 GB testfile.

dd if=/dev/zero of=/var/lib/mysql/ddperftestfile oflag=direct bs=128k count=16k; rm -v /var/lib/mysql/ddperftestfile

ornanovitch

wolfman Thanks again

wolfman Can you try running MySQLTuner https://github.com/major/MySQLTuner-perl

I already played around with MySQLTuner a week ago, and I applied its advices without real improvements even if some were necessary.

wolfman Edit: And can you check the output for creating this 2 GB testfile.

64mb/s, but unfortunately dd is not a very meaningful tool when it comes to ZFS + LXC. That being said, we do have a IO problem since several weeks on our server, I don't know if its directly related to Flarum yet, but I started to look around possible optimizations for InnoDB/ZFS and it looks promising.

My next step is to migrate the LXC to Debian 11 - php7.4

The only remaining question is for us is why is it happening now, why do we have IO problem on the whole server, and why other services such as Nextcloud don't seems to suffer as Flarum does.

wolfman

You are right. ZFS usually compresses Zeroes on the fly which makes it lighning fast - especially if there is no virtualized filesystem of a VM in between, as LXC goes directly to ZFS. On the other hand, 64 MB/s is not especially fast either.

Can you run vmstat -a 1 while testing your SQLs. It produces output like this and adds a new line every second (-a 1):

# vmstat -a 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free  inact active   si   so    bi    bo   in   cs us sy id wa st
 1  0   3840 169552 1164828 2448624    0    0     3    26   17   26  0  0 100  0  0
 0  0   3840 169480 1164860 2449116    0    0     0     0  135  232  0  1 99  0  0
 0  0   3840 169480 1164860 2449116    0    0     0    68  119  217  0  0 100  0  0

The second to last Column cpu wait is always a good indicator if some resources like disk or RAM are slow and the CPU has to wait for it. In an ideal world this value should always be 0.

It might also be possible, that the issue is not with your LXC, but Proxmox itself. Do you have enough free CPU resources and RAM in Proxmox? Also check the IO delay value on your Proxmox host.

ornanovitch

wolfman thanks for those useful inputs, I'll let you know our metrics asap. I already know we have an IO delay issue, thus the vmstat should confirm our problem.

wolfman

ornanovitch Knowing what's the problem is usually half the way! Fingers crossed! 😀

Out of pure interest: Are you using local ZFS storage on your Proxmox host? Or via NFS or iSCSI on something like TrueNAS?