Kolibri: vacuum does not work properly for large DBs in 0.12.x

Created on 21 Aug 2019 · 9Comments · Source: learningequality/kolibri

Observed behavior

ref: https://github.com/learningequality/kolibri-server/issues/20#issuecomment-523139707 from @jredrejo :

A problem with one function that's been executed whenever kolibri starts and keeps the db open while vacuum is done, thus vacuum does not work properly. This is only reproducible in big databases as the one you had. This problem has been fixed in kolibri ( in learningequality/kolibri#5494 ) but the fix is not included in the latest release, it will be included in the 0.13.x version.

Expected behavior

vacuum works as expected

User-facing consequences

from @intelliant01:

the bug results in all sorts of inconsistent behaviour for end users

Errors and logs

…

Steps to reproduce

Start kolibri with
kolibri start --foreground
Stop kolibri with
kolibri stop
sqlite journal files keep there and journal is not written to the database
However, if kolibri is stopped using Ctrl-c in the same window where it's started, all pending data is written to the database and journal files disappear.

Context

0.12.8, but not 0.13.x

backend P1 - important bug changelog

Source

indirectlylit

All 9 comments

Just to understand this right: We want to backport the fixes to 0.12 because it's an LTS, right?

benjaoming on 22 Aug 2019

We want to backport the fixes because 0.13.0 won't be released for a few months. (we don't have an official concept of "LTS" with regard to Kolibri releases)

indirectlylit on 22 Aug 2019

👍1

@intelliant01 FYI we're currently investigating the feasibility of backporting this to 0.12.9

indirectlylit on 23 Oct 2019

@indirectlylit the heads up is much appreciated. Really hoping that this can be backported because this is definitely a big bottleneck for scaling the usage of Kolibri on sqlite backend. Will know only after this porting if anything else needs to be addressed.

intelliant01 on 24 Oct 2019

Not sure if this should go in https://github.com/learningequality/kolibri-server/issues/20 or https://github.com/learningequality/kolibri/issues/5987 or if this is the right place.

@indirectlylit @jredrejo Tested in the following environment -
kolibri 0.12.9b1 deb
kolibri server 0.3.2
sqlite db size ~ 2.7 GB.

kolibri-server.service -

# This provides the Kolibri server service, started by invoking the old
# style /etc/init.d/kolibri-server service for backwards-compatibility.

[Unit]
Description=A high performance web server setup for Kolibri
After=redis.service nginx.service
Wants=network-online.target

[Service]
Type=forking
ExecStart=/etc/init.d/kolibri-server start
ExecStop=/etc/init.d/kolibri-server stop
TimeoutStartSec=infinity
TimeoutStopSec=10
KillMode=mixed

[Install]
WantedBy=multi-user.target

[Timer]
OnStartupSec=20

Observations:

Startup time i.e. time from start to Kolibri being smoothly responsive and usable, has reduced from around 10 minutes to around 6 minutes.

kolibri.txt upon each start after the first post upgrade which involved db update -

WARNING 2019-10-30 21:17:32,150 options Options file /home/mssadmin/.kolibri/options.ini has been updated; server restart is required before change will take effect.
INFO 2019-10-30 21:17:41,077 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-10-30 21:21:16,609 vacuumsqlite Sqlite database Vacuum finished.
INFO 2019-10-30 21:21:17,077 cli Running 'kolibri start' as daemon (system service)
INFO 2019-10-30 21:21:17,079 cli Starting Kolibri background services
INFO 2019-10-30 21:21:17,081 cli Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt
INFO 2019-10-30 21:21:17,223 ping Attempting a ping.
INFO 2019-10-30 21:21:18,720 utils Started new JOBCHECKER thread ID#58a4528c9cf740799f1d9c58731ee6b4
INFO 2019-10-30 21:21:20,551 annotation Updating num_coach_content on existing channels
INFO 2019-10-30 21:21:53,866 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-10-30 21:24:39,192 vacuumsqlite Sqlite database Vacuum finished.
INFO 2019-10-30 21:24:39,193 vacuumsqlite Next Vacuum at 3AM local server time (in 335.3333333333333 minutes).
INFO 2019-10-30 21:25:06,563 ping Ping succeeded! (response: {'id': 426051, 'messages': []})

There is still a sqlite3.OperationalError: database is locked error during start up.

daemon.txt -

INFO     Attempting a ping.
INFO     Started new JOBCHECKER thread ID#58a4528c9cf740799f1d9c58731ee6b4
INFO     Updating num_coach_content on existing channels
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlite3.OperationalError: database is locked

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/bin/kolibri", line 11, in <module>
    load_entry_point('kolibri==0.12.9b1', 'console_scripts', 'kolibri')()
  File "/usr/lib/python3/dist-packages/kolibri/utils/cli.py", line 625, in main
    start(port, daemon=daemon)
  File "/usr/lib/python3/dist-packages/kolibri/utils/cli.py", line 319, in start
    server.start(port=port, run_cherrypy=run_cherrypy)
  File "/usr/lib/python3/dist-packages/kolibri/utils/server.py", line 113, in start
    update_channel_metadata()
  File "/usr/lib/python3/dist-packages/kolibri/core/content/utils/annotation.py", line 73, in update_channel_metadata
    update_num_coach_contents()
  File "/usr/lib/python3/dist-packages/kolibri/core/content/utils/annotation.py", line 167, in update_num_coach_contents
    .values(num_coach_contents=cast(ContentNodeTable.c.coach_content, Integer()))
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 948, in execute
    return meth(self, multiparams, params)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1200, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
    exc_info
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/util/compat.py", line 265, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/util/compat.py", line 248, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/lib/python3/dist-packages/kolibri/dist/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) database is locked [SQL: 'UPDATE content_contentnode SET num_coach_contents=CAST(content_contentnode.coach_content AS INTEGER) WHERE content_contentnode.kind != ?'] [parameters: ('topic',)] (Background on this error at: http://sqlalche.me/e/e3q8)
INFO     Sqlite database Vacuum finished.
INFO     Next Vacuum at 3AM local server time (in 335.3333333333333 minutes).
INFO     Ping succeeded! (response: {'id': 426051, 'messages': []})
INFO     Sleeping for 1440.0 minutes.

Shutdown is still unclean.

Lines from kolibri.txt for each shutdown -

INFO 2019-10-30 21:28:46,286 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
ERROR 2019-10-30 21:28:47,966 cli During graceful shutdown, server says: Failed to start (check log file: /home/mssadmin/.kolibri/logs/daemon.txt) (6)
ERROR 2019-10-30 21:28:48,093 cli Not responding, killing with force

# systemctl status kolibri-server kolibri
● kolibri-server.service - A high performance web server setup for Kolibri
   Loaded: loaded (/lib/systemd/system/kolibri-server.service; enabled; vendor preset: enabled)
   Active: failed (Result: timeout) since Wed 2019-10-30 21:46:36 IST; 43s ago
  Process: 10583 ExecStop=/etc/init.d/kolibri-server stop (code=killed, signal=TERM)
  Process: 10239 ExecStart=/etc/init.d/kolibri-server start (code=exited, status=0/SUCCESS)
 Main PID: 10521 (code=killed, signal=KILL)

Oct 30 21:43:19 server kolibri-server[10239]: [uWSGI] getting INI configuration from /etc/kolibri/dist/uwsgi.ini
Oct 30 21:43:20 server systemd[1]: Started A high performance web server setup for Kolibri.
Oct 30 21:46:15 server systemd[1]: Stopping A high performance web server setup for Kolibri...
Oct 30 21:46:26 server systemd[1]: kolibri-server.service: Stopping timed out. Terminating.
Oct 30 21:46:36 server systemd[1]: kolibri-server.service: State 'stop-sigterm' timed out. Killing.
Oct 30 21:46:36 server systemd[1]: kolibri-server.service: Killing process 10521 (uwsgi) with signal SIGKILL.
Oct 30 21:46:36 server systemd[1]: kolibri-server.service: Killing process 10595 (systemctl) with signal SIGKILL.
Oct 30 21:46:36 server systemd[1]: kolibri-server.service: Main process exited, code=killed, status=9/KILL
Oct 30 21:46:36 server systemd[1]: kolibri-server.service: Failed with result 'timeout'.
Oct 30 21:46:36 server systemd[1]: Stopped A high performance web server setup for Kolibri.

● kolibri.service - LSB: kolibri daemon, an offline education platform
   Loaded: loaded (/etc/init.d/kolibri; disabled; vendor preset: enabled)
   Active: inactive (dead)

Oct 30 21:42:58 server kolibri[10319]: INFO     Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt
Oct 30 21:43:00 server systemd[1]: Started LSB: kolibri daemon, an offline education platform.
Oct 30 21:46:27 server systemd[1]: Stopping LSB: kolibri daemon, an offline education platform...
Oct 30 21:46:28 server su[10652]: Successful su for mssadmin by root
Oct 30 21:46:28 server su[10652]: + ??? root:mssadmin
Oct 30 21:46:28 server su[10652]: pam_unix(su:session): session opened for user mssadmin by (uid=0)
Oct 30 21:46:56 server kolibri[10626]: INFO     Running Kolibri with the following settings: kolibri.deployment.default.settings.base
Oct 30 21:47:06 server kolibri[10626]: ERROR    During graceful shutdown, server says: Failed to start (check log file: /home/mssadmin/.kolibri/logs/daemon.txt) (6)
Oct 30 21:47:07 server kolibri[10626]: ERROR    Not responding, killing with force
Oct 30 21:47:07 server systemd[1]: Stopped LSB: kolibri daemon, an offline education platform.

A line in kolibri.txt is INFO 2019-10-30 21:21:17,081 cli Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt . I think it should be daemon.txt instead of kolibri.txt
If possible, addition of timestamps in daemon.txt shall help to co-orelate with the events being logged in kolibri.txt.

intelliant01 on 30 Oct 2019

just a heads-up that beta1 was tagged before #5987 was merged. I'll tag a new beta now

indirectlylit on 30 Oct 2019

@indirectlylit do you want me to test with beta2 and check if I have different results?

intelliant01 on 31 Oct 2019

Tested in the following environment -
kolibri 0.12.9b2 deb
kolibri server 0.3.2
sqlite db size ~ 2.7 GB.
Hardware - Celeron Dual core + 4 GB RAM

Observations:

Startup time i.e. time from start to Kolibri being smoothly responsive and usable, has reduced from around 10 minutes to under 5 minutes.

kolibri.txt upon each start after the first post upgrade which involved db update and took around 9 minutes -

WARNING 2019-10-31 12:18:28,717 options Options file /home/mssadmin/.kolibri/options.ini has been updated; server restart is required before change will take effect.
INFO 2019-10-31 12:18:37,470 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-10-31 12:18:39,206 cli Running 'kolibri start' as daemon (system service)
INFO 2019-10-31 12:18:39,207 cli Starting Kolibri background services
INFO 2019-10-31 12:18:39,209 cli Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt
INFO 2019-10-31 12:18:39,326 ping Attempting a ping.
INFO 2019-10-31 12:18:40,176 utils Started new JOBCHECKER thread ID#6ae8975f4569472e9236c2e7b0d994d2
INFO 2019-10-31 12:18:40,178 server Starting Kolibri 0.12.9b2
INFO 2019-10-31 12:19:02,129 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-10-31 12:22:31,282 vacuumsqlite Sqlite database Vacuum finished.
INFO 2019-10-31 12:22:31,408 vacuumsqlite Next Vacuum at 3AM local server time (in 877.4666666666667 minutes).
INFO 2019-10-31 12:22:47,148 ping Ping succeeded! (response: {'id': 427166, 'messages': []})
INFO 2019-10-31 12:23:09,661 ping Sleeping for 1440.0 minutes.

No more db locking error in daemon.txt

INFO     Attempting a ping.
INFO     Starting Kolibri 0.12.9b2
INFO     Started new JOBCHECKER thread ID#6ae8975f4569472e9236c2e7b0d994d2
INFO     Sqlite database Vacuum finished.
INFO     Next Vacuum at 3AM local server time (in 877.4666666666667 minutes).
INFO     Ping succeeded! (response: {'id': 427166, 'messages': []})
INFO     Sleeping for 1440.0 minutes.

Shutdown is clean except the timeout for kolibri-server despite increasing TimeoutStopSec=60 in kolibri-server.service

kolibri.txt

INFO 2019-10-31 12:25:33,691 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base
INFO 2019-10-31 12:25:36,845 cli Kolibri background services have successfully been stopped.
INFO 2019-10-31 12:25:45,208 apps Running Kolibri with the following settings: kolibri.deployment.default.settings.base

# systemctl status kolibri-server kolibri
● kolibri-server.service - A high performance web server setup for Kolibri
   Loaded: loaded (/lib/systemd/system/kolibri-server.service; enabled; vendor preset: enabled)
   Active: failed (Result: signal) since Thu 2019-10-31 12:26:07 IST; 5min ago
  Process: 7342 ExecStop=/etc/init.d/kolibri-server stop (code=exited, status=0/SUCCESS)
  Process: 7052 ExecStart=/etc/init.d/kolibri-server start (code=exited, status=0/SUCCESS)
 Main PID: 7198 (code=killed, signal=KILL)

Oct 31 12:18:26 server su[7073]: + ??? root:mssadmin
Oct 31 12:18:26 server su[7073]: pam_unix(su:session): session opened for user mssadmin by (uid=0)
Oct 31 12:18:28 server kolibri-server[7052]: WARNING  Options file /home/mssadmin/.kolibri/options.ini has been updated; server restart is required before change will take effe
Oct 31 12:18:29 server kolibri-server[7052]: debconf: DbDriver "passwords" warning: could not open /var/cache/debconf/passwords.dat: Permission denied
Oct 31 12:18:56 server kolibri-server[7052]: [uWSGI] getting INI configuration from /etc/kolibri/dist/uwsgi.ini
Oct 31 12:18:56 server systemd[1]: Started A high performance web server setup for Kolibri.
Oct 31 12:25:21 server systemd[1]: Stopping A high performance web server setup for Kolibri...
Oct 31 12:26:07 server systemd[1]: kolibri-server.service: Main process exited, code=killed, status=9/KILL
Oct 31 12:26:07 server systemd[1]: kolibri-server.service: Failed with result 'signal'.
Oct 31 12:26:07 server systemd[1]: Stopped A high performance web server setup for Kolibri.

● kolibri.service - LSB: kolibri daemon, an offline education platform
   Loaded: loaded (/etc/init.d/kolibri; disabled; vendor preset: enabled)
   Active: inactive (dead)

Oct 31 12:18:39 server kolibri[7124]: INFO     Running 'kolibri start' as daemon (system service)
Oct 31 12:18:39 server kolibri[7124]: INFO     Starting Kolibri background services
Oct 31 12:18:39 server kolibri[7124]: INFO     Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt
Oct 31 12:18:39 server systemd[1]: Started LSB: kolibri daemon, an offline education platform.
Oct 31 12:25:27 server systemd[1]: Stopping LSB: kolibri daemon, an offline education platform...
Oct 31 12:25:27 server su[7416]: Successful su for mssadmin by root
Oct 31 12:25:27 server su[7416]: + ??? root:mssadmin
Oct 31 12:25:33 server kolibri[7385]: INFO     Running Kolibri with the following settings: kolibri.deployment.default.settings.base
Oct 31 12:25:36 server kolibri[7385]: INFO     Kolibri background services have successfully been stopped.
Oct 31 12:25:37 server systemd[1]: Stopped LSB: kolibri daemon, an offline education platform.

A line in kolibri.txt is INFO 2019-10-30 21:21:17,081 cli Going to daemon mode, logging to /home/mssadmin/.kolibri/logs/kolibri.txt . I think it should be daemon.txt instead of kolibri.txt
If possible, addition of timestamps in daemon.txt shall help to co-orelate with the events being logged in kolibri.txt.

intelliant01 on 31 Oct 2019

👀1 🎉1

HI @intelliant01, thanks for your intensive and patient tests.
It seems the problem that triggered this issue is finally solved (and it brought other benefits as the reduction in the start up time) so I am closing this issue.
About your latest points 4 & 5:

This is the only place where daemon.txt is used:
https://github.com/learningequality/kolibri/blob/develop/kolibri/utils/cli.py#L488-L491
You can see it outputs the error messages CherryPy sends to the output and error consoles. If CherryPy is not used (for example when using kolibri-server that replaces it by uwsgi) nothing will go there. CherryPy does not allow any kind of control over its messages, as an example, it's not possible to change its log level from error to warning. Honestly, I'd remove any reference to this log file as it's almost useless.
So:
For point 4: kolibri.txt is the real logging file, that's controled by kolibri and where kolibri messages are sent, so I think that message is correct
For point 5: daemon.txt is mostly useless and it's not under kolibri developers control.
If you are not satisfied with this answer, please, feel free to open a new issue to deal with these messages. We'll be glad to discuss it and add all the contributions to improve debugging errors.