database lock error by frequent operation of sqlite-related plugins

[dgy18787]

Hello,

I have updated the SQLite and struct, ratings plugins to the latest version, but these days "database locked" error often occurs and it makes the DokuWiki fail to function.

The error seems to happen in the following processes, based on the error log of DokuWiki:

First, the DokuWiki exceeds the IO limited by the server: 2023-12-09 07:48:07 /path_doku/inc/io.php(538) E_ERROR: Allowed memory size of 67108864 bytes exhausted (tried to allocate 16777224 bytes)

then, the SQLite seems to try to be in WAL mode but failed:

2023-12-09 13:12:51 /path_doku/lib/plugins/sqlite/SQLiteDB.php(132) SQLite: Could not set WAL mode.
  {
      "errorInfo": null
  }

then, the database is locked:

2023-12-09 13:13:01 /path_doku/lib/plugins/sqlite/SQLiteDB.php(473) SQLite: Could not read dbversion from opt table due to unexpected error
  {
      "dbname": "struct",
      "exception": "PDOException",
      "message": "SQLSTATE[HY000]: General error: 5 database is locked",
      "code": 0
  }

and more error:

2023-12-09 13:13:11 /path_doku/lib/plugins/sqlite/SQLiteDB.php(132) PDOException: SQLSTATE[HY000]: General error: 5 database is locked
  #0 /path_doku/lib/plugins/sqlite/SQLiteDB.php(170): dokuwiki\plugin\sqlite\SQLiteDB->query('CREATE TABLE IF...')
  #1 /path_doku/lib/plugins/sqlite/SQLiteDB.php(479): dokuwiki\plugin\sqlite\SQLiteDB->exec('CREATE TABLE IF...')
  #2 /path_doku/lib/plugins/sqlite/SQLiteDB.php(404): dokuwiki\plugin\sqlite\SQLiteDB->currentDbVersion()
  #3 /path_doku/lib/plugins/sqlite/SQLiteDB.php(79): dokuwiki\plugin\sqlite\SQLiteDB->applyMigrations()
  #4 /path_doku/lib/plugins/struct/helper/db.php(27): dokuwiki\plugin\sqlite\SQLiteDB->__construct('struct', '/path...')
  #5 /path_doku/lib/plugins/struct/helper/db.php(50): helper_plugin_struct_db->init()
  #6 /path_doku/lib/plugins/struct/meta/Assignments.php(51): helper_plugin_struct_db->getDB()
  #7 /path_doku/lib/plugins/struct/meta/Assignments.php(37): dokuwiki\plugin\struct\meta\Assignments->__construct()
  #8 /path_doku/lib/plugins/struct/action/cache.php(54): dokuwiki\plugin\struct\meta\Assignments::getInstance()
  #9 /path_doku/inc/Extension/EventHandler.php(80): action_plugin_struct_cache->handleCacheSchemachange(Object(dokuwiki\Extension\Event), NULL)
  #10 /path_doku/inc/Extension/Event.php(74): dokuwiki\Extension\EventHandler->process_event(Object(dokuwiki\Extension\Event), 'BEFORE')
  #11 /path_doku/inc/Extension/Event.php(132): dokuwiki\Extension\Event->advise_before(true)
  #12 /path_doku/inc/Extension/Event.php(199): dokuwiki\Extension\Event->trigger(Array, true)
  #13 /path_doku/inc/Cache/Cache.php(86): dokuwiki\Extension\Event::createAndTrigger('PARSER_CACHE_US...', Object(dokuwiki\Cache\CacheRenderer), Array)
  #14 /path_doku/inc/parserutils.php(152): dokuwiki\Cache\Cache->useCache()
  #15 /path_doku/inc/parserutils.php(96): p_cached_output('/path...', 'xhtml', 'sidebar')
  #16 /path_doku/inc/template.php(1592): p_wiki_xhtml('sidebar', '', false)
  #17 /path_doku/lib/tpl/dokuwiki/main.php(53): tpl_include_page('sidebar', true, true)
  #18 /path_doku/inc/actions.php(27): include('/path...')
  #19 /path_doku/doku.php(126): act_dispatch()
  #20 {main}

When the error occurs, at first, the whole page of the site (like the index) cannot be rendered properly, it will stop the rendering at the sidebar and show the error message on the position where the sidebar should be; if one refresh the page several times, the page will be broken and only a error information with the hint saying the sqlite might have problems:

PDOException: SQLSTATE[HY000]: General error: 5 database is locked
An unforeseen error has occured. This is most likely a bug somewhere. It might be a problem in the sqlite plugin.

More info has been written to the DokuWiki error log.

I suspected the issue was caused by ratings plugins as the plugins is not updated for years. but after disabling it, the SQLite didn't work again and this time it was caused by struct. the strange thing is that we have not updated the struct data for a long time (just look up, no write or update), I have no idea what kind of operation caused the database lock.

I think this error is also related to a limited RAM assigned to a single php thread and a limited time of execution. Is there any possible solution for it? Thanks!

[splitbrain]

Some observations:

• 64MB of RAM is unusually low, but this shouldn't be the problem
• it's weird that WAL mode can't be enabled. No idea under what circumstances that happens
• your error seems to happen inside a migration (applyMigrations() -> CREATE TABLE IF...) so what version is your DB currently in?
• you don't mention the used PHP and sqlite versions
• you mention a time limit but not what that limit is
• could you provide a copy of your database for further analysis?

[dgy18787]

Hello @splitbrain,

Sorry for not providing the necessary information in the post. I'll add them up here.

• 64MB of RAM is unusually low, but this shouldn't be the problem

I don't know why the RAM is restricted on the server, I tried to extend the RAM in the PHP config file, but it didn't solve the problem.

• your error seems to happen inside a migration (applyMigrations() -> CREATE TABLE IF...) so what version is your DB currently in?

My database is locked now so I cannot check the dbversion; this situation often happened recently, my only solution is to download and delete the .db file under the meta folder, then dump it as sql file and import it again; and after several days the database is locked again.

From the file I have downloaded from the meta folder, the dbversion is 19.

• you don't mention the used PHP and sqlite versions

The SQLite version is 3.39.4 via $dbh->query('select sqlite_version()')->fetch()[0] My PHP version is 7.4, and here is the php.ini (modified but the problem still exists)

allow_url_fopen = Off
display_errors = Off
enable_dl = Off
file_uploads = On
max_execution_time = 300
max_input_time = 300
max_input_vars = 1000
memory_limit = 1024M
post_max_size = 64M
session.gc_maxlifetime = 1440
session.save_path = "/var/cpanel/php/sessions/ea-php74"
upload_max_filesize = 16M
zlib.output_compression = Off

• you mention a time limit but not what that limit is

it's max_execution_time. It was 120s before, I have changed it to 300s.

• could you provide a copy of your database for further analysis?

yes, please refer to https://demodb.org/struct_demodbtest.tar.gz

[splitbrain]

version 19 is the most recent struct db. I think the migration is run because if we encounter an error in reading the DB version, we log an error but still try to create the opts table and return version 0. This obviously makes no sense. I guess we need to throw an exception there?

https://github.com/cosmocode/sqlite/blob/6cb8d74b9460386ebe827296478b5f3d5e4b00cb/SQLiteDB.php#L462-L475

Of course this does not explain the actual problem causing the database lock...

@annda can you look into this and see if you can reproduce the problem?

[dgy18787]

Update:

I have also tried to check the dbversion of struct database directly from the interface provided by SQLite plugin, but get a SQLSTATE[HY000]: General error: 5 database is locked return. I have checked the server and found that there seems no IO, but the database is still being locked.

[dgy18787]

Hello @splitbrain ,

Today I recovered my struct database and open the debug log in the admin panel. I notice that the struct is keeping execute some queries while I don't know what are they for.

My virtual server's IO has been restricted to 2MB/s and seems the queries are always eat all IO up so the server runs slowly. Is it a potential cause of the problem?

Followings are pieces of the selected log:

2023-12-17 15:47:57     [sqlite] slow query:  (3.9972829818726s)
  {
      "sql": " SELECT data_general_meta.rid AS rid,\ndata_general_meta.pid AS PID,\ndata_general_meta.rev AS rev,\nschema_assignments.assigned AS ASSIGNED,\ndata_general_meta.col3 AS C0,\ndata_general_meta.col1 AS C1,\ndata_general_meta.col4 AS C2\n   FROM \ndata_general_meta AS data_general_meta\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_general_meta.pid != ''\n                    AND data_general_meta.pid = schema_assignments.pid\n                    AND schema_assignments.tbl = 'general_meta'\n  WHERE  ( ( data_general_meta.pid = '' OR ( GETACCESSLEVEL(data_general_meta.pid) > 0 AND PAGEEXISTS(data_general_meta.pid) = 1 AND (data_general_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_general_meta.pid) AND data_general_meta.latest = 1) OR (IS_PUBLISHER(data_general_meta.pid) !=1 AND data_general_meta.published = 1) ) )\nGROUP BY data_general_meta.pid,\ndata_general_meta.rid,\nC0,\nC1,\nC2\n",
      "parameters": [],
      "backtrace": [
          "act_dispatch() called at \/path\/doku.php:126",
          "include(\"\/path\/lib\/tpl\/dokuwiki\/main.php\") called at \/path\/inc\/actions.php:27",
          "tpl_content() called at \/path\/lib\/tpl\/dokuwiki\/main.php:69",
          "dokuwiki\\Extension\\Event::createAndTrigger(\"TPL_ACT_RENDER\", \"show\", \"tpl_content_core\") called at \/path\/inc\/template.php:85",
          "dokuwiki\\Extension\\Event->trigger(\"tpl_content_core\", \"1\") called at \/path\/inc\/Extension\/Event.php:199",
          "call_user_func_array(\"tpl_content_core\", [Array]) called at \/path\/inc\/Extension\/Event.php:133",
          "tpl_content_core(\"show\") called at :",
          "dokuwiki\\Action\\Show->tplContent() called at \/path\/inc\/template.php:100",
          "dokuwiki\\Ui\\PageView->show() called at \/path\/inc\/Action\/Show.php:37",
          "p_wiki_xhtml(\"search:model_result\", \"0\", \"1\", \"\") called at \/path\/inc\/Ui\/PageView.php:68",
          "p_cached_output(\"\/path\/data\/pages\/search\/model_result.txt\", \"xhtml\", \"search:model_result\") called at \/path\/inc\/parserutils.php:96",
          "p_render(\"xhtml\", [Array], [NULL]) called at \/path\/inc\/parserutils.php:158",
          "Doku_Renderer->plugin(\"struct_filter\", [Array], \"5\", \"---- struct filter ----\\nschema: general_meta\\ncols: year_of_release\\ncols: factory, year_of_release,  with_demo\\n----\") called at \/path\/inc\/parserutils.php:700",
          "syntax_plugin_struct_filter->render(\"xhtml\", [Object Doku_Renderer_xhtml], [Array]) called at \/path\/inc\/parser\/renderer.php:119",
          "dokuwiki\\plugin\\struct\\meta\\Aggregation->__construct(\"search:model_result\", \"xhtml\", [Object Doku_Renderer_xhtml], [Object dokuwiki\\plugin\\struct\\meta\\SearchConfig]) called at \/path\/lib\/plugins\/struct\/syntax\/filter.php:39",
          "dokuwiki\\plugin\\struct\\meta\\Search->execute() called at \/path\/lib\/plugins\/struct\/meta\/Aggregation.php:65",
          "dokuwiki\\plugin\\sqlite\\SQLiteDB->query(\" SELECT data_general_meta.rid AS rid,\\ndata_general_meta.pid AS PID,\\ndata_general_meta.rev AS rev,\\nschema_assignments.assigned AS ASSIGNED,\\ndata_general_meta.col3 AS C0,\\ndata_general_meta.col1 AS C1,\\ndata_general_meta.col4 AS C2\\n   FROM \\ndata_general_meta AS data_general_meta\\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_general_meta.pid != ''\\n                    AND data_general_meta.pid = schema_assignments.pid\\n                    AND schema_assignments.tbl = 'general_meta'\\n  WHERE  ( ( data_general_meta.pid = '' OR ( GETACCESSLEVEL(data_general_meta.pid) > 0 AND PAGEEXISTS(data_general_meta.pid) = 1 AND (data_general_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_general_meta.pid) AND data_general_meta.latest = 1) OR (IS_PUBLISHER(data_general_meta.pid) !=1 AND data_general_meta.published = 1) ) )\\nGROUP BY data_general_meta.pid,\\ndata_general_meta.rid,\\nC0,\\nC1,\\nC2\\n\", [Array]) called at \/path\/lib\/plugins\/struct\/meta\/Search.php:457"
      ]
  }

2023-12-17 15:52:43     [sqlite] slow query:  (0.2959680557251s)
  {
      "sql": " SELECT data_song_meta.rid AS rid,\ndata_song_meta.pid AS PID,\ndata_song_meta.rev AS rev,\nschema_assignments.assigned AS ASSIGNED,\nSTRUCT_JSON(data_song_meta.pid, T9.title) AS C0,\nGROUP_CONCAT_DISTINCT(M10.value, '\n!_-_-_-_-_!\n') AS C1,\nGROUP_CONCAT_DISTINCT(M11.value, '\n!_-_-_-_-_!\n') AS C2,\nGROUP_CONCAT_DISTINCT(M12.value, '\n!_-_-_-_-_!\n') AS C3,\nGROUP_CONCAT_DISTINCT(M13.value, '\n!_-_-_-_-_!\n') AS C4,\nGROUP_CONCAT_DISTINCT(M14.value, '\n!_-_-_-_-_!\n') AS C5,\nGROUP_CONCAT_DISTINCT(M15.value, '\n!_-_-_-_-_!\n') AS C6\n   FROM \ndata_song_meta AS data_song_meta\nLEFT OUTER JOIN multi_song_meta AS MN19 ON data_song_meta.pid = MN19.pid AND data_song_meta.rid = MN19.rid AND\n                     data_song_meta.rev = MN19.rev AND\n                     MN19.colref = 5\nLEFT OUTER JOIN multi_song_meta AS MN18 ON data_song_meta.pid = MN18.pid AND data_song_meta.rid = MN18.rid AND\n                     data_song_meta.rev = MN18.rev AND\n                     MN18.colref = 4\nLEFT OUTER JOIN multi_song_meta AS MN17 ON data_song_meta.pid = MN17.pid AND data_song_meta.rid = MN17.rid AND\n                     data_song_meta.rev = MN17.rev AND\n                     MN17.colref = 1\nLEFT OUTER JOIN multi_song_meta AS MN16 ON data_song_meta.pid = MN16.pid AND data_song_meta.rid = MN16.rid AND\n                     data_song_meta.rev = MN16.rev AND\n                     MN16.colref = 2\nLEFT OUTER JOIN multi_song_meta AS M15 ON data_song_meta.pid = M15.pid AND data_song_meta.rid = M15.rid AND\n                     data_song_meta.rev = M15.rev AND\n                     M15.colref = 8\nLEFT OUTER JOIN multi_song_meta AS M14 ON data_song_meta.pid = M14.pid AND data_song_meta.rid = M14.rid AND\n                     data_song_meta.rev = M14.rev AND\n                     M14.colref = 7\nLEFT OUTER JOIN multi_song_meta AS M13 ON data_song_meta.pid = M13.pid AND data_song_meta.rid = M13.rid AND\n                     data_song_meta.rev = M13.rev AND\n                     M13.colref = 6\nLEFT OUTER JOIN multi_song_meta AS M12 ON data_song_meta.pid = M12.pid AND data_song_meta.rid = M12.rid AND\n                     data_song_meta.rev = M12.rev AND\n                     M12.colref = 5\nLEFT OUTER JOIN multi_song_meta AS M11 ON data_song_meta.pid = M11.pid AND data_song_meta.rid = M11.rid AND\n                     data_song_meta.rev = M11.rev AND\n                     M11.colref = 4\nLEFT OUTER JOIN multi_song_meta AS M10 ON data_song_meta.pid = M10.pid AND data_song_meta.rid = M10.rid AND\n                     data_song_meta.rev = M10.rev AND\n                     M10.colref = 3\nLEFT OUTER JOIN titles AS T9 ON data_song_meta.pid = T9.pid\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_song_meta.pid != ''\n                    AND data_song_meta.pid = schema_assignments.pid\n                    AND schema_assignments.tbl = 'song_meta'\n  WHERE  ( ( data_song_meta.pid = '' OR ( GETACCESSLEVEL(data_song_meta.pid) > 0 AND PAGEEXISTS(data_song_meta.pid) = 1 AND (data_song_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_song_meta.pid) AND data_song_meta.latest = 1) OR (IS_PUBLISHER(data_song_meta.pid) !=1 AND data_song_meta.published = 1) ) AND ( MN16.value = :val5 AND MN17.value = :val6 AND MN18.value = :val7 AND MN19.value = :val8 ) )\nGROUP BY data_song_meta.pid,\ndata_song_meta.rid,\nC0\n",
      "parameters": [
          "\u65af\u5361\u5e03\u7f57\u96c6\u5e02",
          "Lightly Row",
          "John Pond Ordway",
          "2013"
      ],
      "backtrace": [
          "act_dispatch() called at \/path\/doku.php:126",
          "include(\"\/path\/lib\/tpl\/dokuwiki\/main.php\") called at \/path\/inc\/actions.php:27",
          "tpl_content() called at \/path\/lib\/tpl\/dokuwiki\/main.php:69",
          "dokuwiki\\Extension\\Event::createAndTrigger(\"TPL_ACT_RENDER\", \"show\", \"tpl_content_core\") called at \/path\/inc\/template.php:85",
          "dokuwiki\\Extension\\Event->trigger(\"tpl_content_core\", \"1\") called at \/path\/inc\/Extension\/Event.php:199",
          "call_user_func_array(\"tpl_content_core\", [Array]) called at \/path\/inc\/Extension\/Event.php:133",
          "tpl_content_core(\"show\") called at :",
          "dokuwiki\\Action\\Show->tplContent() called at \/path\/inc\/template.php:100",
          "dokuwiki\\Ui\\PageView->show() called at \/path\/inc\/Action\/Show.php:37",
          "p_wiki_xhtml(\"songs:sort_by\", \"0\", \"1\", \"\") called at \/path\/inc\/Ui\/PageView.php:68",
          "p_cached_output(\"\/path\/data\/pages\/songs\/sort_by.txt\", \"xhtml\", \"songs:sort_by\") called at \/path\/inc\/parserutils.php:96",
          "p_render(\"xhtml\", [Array], [NULL]) called at \/path\/inc\/parserutils.php:158",
          "Doku_Renderer->plugin(\"struct_table\", [Array], \"5\", \"---- struct table ----\\nschema: song_meta\\ncols: %title%,composer,lyricist,original_date,genre,region,original_instruments\\nrownumbers: 1\\ndynfilters: 1\\ncsv:0\\n----\") called at \/path\/inc\/parserutils.php:700",
          "syntax_plugin_struct_table->render(\"xhtml\", [Object Doku_Renderer_xhtml], [Array]) called at \/path\/inc\/parser\/renderer.php:119",
          "dokuwiki\\plugin\\struct\\meta\\AggregationTable->__construct(\"songs:sort_by\", \"xhtml\", [Object Doku_Renderer_xhtml], [Object dokuwiki\\plugin\\struct\\meta\\SearchConfig]) called at \/path\/lib\/plugins\/struct\/syntax\/table.php:119",
          "dokuwiki\\plugin\\struct\\meta\\Aggregation->__construct(\"songs:sort_by\", \"xhtml\", [Object Doku_Renderer_xhtml], [Object dokuwiki\\plugin\\struct\\meta\\SearchConfig]) called at \/path\/lib\/plugins\/struct\/meta\/AggregationTable.php:24",
          "dokuwiki\\plugin\\struct\\meta\\Search->execute() called at \/path\/lib\/plugins\/struct\/meta\/Aggregation.php:65",
          "dokuwiki\\plugin\\sqlite\\SQLiteDB->query(\" SELECT data_song_meta.rid AS rid,\\ndata_song_meta.pid AS PID,\\ndata_song_meta.rev AS rev,\\nschema_assignments.assigned AS ASSIGNED,\\nSTRUCT_JSON(data_song_meta.pid, T9.title) AS C0,\\nGROUP_CONCAT_DISTINCT(M10.value, '\\n!_-_-_-_-_!\\n') AS C1,\\nGROUP_CONCAT_DISTINCT(M11.value, '\\n!_-_-_-_-_!\\n') AS C2,\\nGROUP_CONCAT_DISTINCT(M12.value, '\\n!_-_-_-_-_!\\n') AS C3,\\nGROUP_CONCAT_DISTINCT(M13.value, '\\n!_-_-_-_-_!\\n') AS C4,\\nGROUP_CONCAT_DISTINCT(M14.value, '\\n!_-_-_-_-_!\\n') AS C5,\\nGROUP_CONCAT_DISTINCT(M15.value, '\\n!_-_-_-_-_!\\n') AS C6\\n   FROM \\ndata_song_meta AS data_song_meta\\nLEFT OUTER JOIN multi_song_meta AS MN19 ON data_song_meta.pid = MN19.pid AND data_song_meta.rid = MN19.rid AND\\n                     data_song_meta.rev = MN19.rev AND\\n                     MN19.colref = 5\\nLEFT OUTER JOIN multi_song_meta AS MN18 ON data_song_meta.pid = MN18.pid AND data_song_meta.rid = MN18.rid AND\\n                     data_song_meta.rev = MN18.rev AND\\n                     MN18.colref = 4\\nLEFT OUTER JOIN multi_song_meta AS MN17 ON data_song_meta.pid = MN17.pid AND data_song_meta.rid = MN17.rid AND\\n                     data_song_meta.rev = MN17.rev AND\\n                     MN17.colref = 1\\nLEFT OUTER JOIN multi_song_meta AS MN16 ON data_song_meta.pid = MN16.pid AND data_song_meta.rid = MN16.rid AND\\n                     data_song_meta.rev = MN16.rev AND\\n                     MN16.colref = 2\\nLEFT OUTER JOIN multi_song_meta AS M15 ON data_song_meta.pid = M15.pid AND data_song_meta.rid = M15.rid AND\\n                     data_song_meta.rev = M15.rev AND\\n                     M15.colref = 8\\nLEFT OUTER JOIN multi_song_meta AS M14 ON data_song_meta.pid = M14.pid AND data_song_meta.rid = M14.rid AND\\n                     data_song_meta.rev = M14.rev AND\\n                     M14.colref = 7\\nLEFT OUTER JOIN multi_song_meta AS M13 ON data_song_meta.pid = M13.pid AND data_song_meta.rid = M13.rid AND\\n                     data_song_meta.rev = M13.rev AND\\n                     M13.colref = 6\\nLEFT OUTER JOIN multi_song_meta AS M12 ON data_song_meta.pid = M12.pid AND data_song_meta.rid = M12.rid AND\\n                     data_song_meta.rev = M12.rev AND\\n                     M12.colref = 5\\nLEFT OUTER JOIN multi_song_meta AS M11 ON data_song_meta.pid = M11.pid AND data_song_meta.rid = M11.rid AND\\n                     data_song_meta.rev = M11.rev AND\\n                     M11.colref = 4\\nLEFT OUTER JOIN multi_song_meta AS M10 ON data_song_meta.pid = M10.pid AND data_song_meta.rid = M10.rid AND\\n                     data_song_meta.rev = M10.rev AND\\n                     M10.colref = 3\\nLEFT OUTER JOIN titles AS T9 ON data_song_meta.pid = T9.pid\\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_song_meta.pid != ''\\n                    AND data_song_meta.pid = schema_assignments.pid\\n                    AND schema_assignments.tbl = 'song_meta'\\n  WHERE  ( ( data_song_meta.pid = '' OR ( GETACCESSLEVEL(data_song_meta.pid) > 0 AND PAGEEXISTS(data_song_meta.pid) = 1 AND (data_song_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_song_meta.pid) AND data_song_meta.latest = 1) OR (IS_PUBLISHER(data_song_meta.pid) !=1 AND data_song_meta.published = 1) ) AND ( MN16.value = :val5 AND MN17.value = :val6 AND MN18.value = :val7 AND MN19.value = :val8 ) )\\nGROUP BY data_song_meta.pid,\\ndata_song_meta.rid,\\nC0\\n\", [Array]) called at \/path\/lib\/plugins\/struct\/meta\/Search.php:457"
      ]
  }

2023-12-17 15:50:37     [sqlite] slow query:  (3.4971489906311s)
  {
      "sql": " SELECT data_general_meta.rid AS rid,\ndata_general_meta.pid AS PID,\ndata_general_meta.rev AS rev,\nschema_assignments.assigned AS ASSIGNED,\ndata_general_meta.col3 AS C0,\ndata_general_meta.col1 AS C1,\ndata_general_meta.col4 AS C2\n   FROM \ndata_general_meta AS data_general_meta\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_general_meta.pid != ''\n                    AND data_general_meta.pid = schema_assignments.pid\n                    AND schema_assignments.tbl = 'general_meta'\n  WHERE  ( ( data_general_meta.pid = '' OR ( GETACCESSLEVEL(data_general_meta.pid) > 0 AND PAGEEXISTS(data_general_meta.pid) = 1 AND (data_general_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_general_meta.pid) AND data_general_meta.latest = 1) OR (IS_PUBLISHER(data_general_meta.pid) !=1 AND data_general_meta.published = 1) ) )\nGROUP BY data_general_meta.pid,\ndata_general_meta.rid,\nC0,\nC1,\nC2\n",
      "parameters": [],
      "backtrace": [
          "act_dispatch() called at \/path\/doku.php:126",
          "include(\"\/path\/lib\/tpl\/dokuwiki\/main.php\") called at \/path\/inc\/actions.php:27",
          "tpl_content() called at \/path\/lib\/tpl\/dokuwiki\/main.php:69",
          "dokuwiki\\Extension\\Event::createAndTrigger(\"TPL_ACT_RENDER\", \"show\", \"tpl_content_core\") called at \/path\/inc\/template.php:85",
          "dokuwiki\\Extension\\Event->trigger(\"tpl_content_core\", \"1\") called at \/path\/inc\/Extension\/Event.php:199",
          "call_user_func_array(\"tpl_content_core\", [Array]) called at \/path\/inc\/Extension\/Event.php:133",
          "tpl_content_core(\"show\") called at :",
          "dokuwiki\\Action\\Show->tplContent() called at \/path\/inc\/template.php:100",
          "dokuwiki\\Ui\\PageView->show() called at \/path\/inc\/Action\/Show.php:37",
          "p_wiki_xhtml(\"search:model_result\", \"0\", \"1\", \"\") called at \/path\/inc\/Ui\/PageView.php:68",
          "p_cached_output(\"\/path\/data\/pages\/search\/model_result.txt\", \"xhtml\", \"search:model_result\") called at \/path\/inc\/parserutils.php:96",
          "p_render(\"xhtml\", [Array], [NULL]) called at \/path\/inc\/parserutils.php:158",
          "Doku_Renderer->plugin(\"struct_filter\", [Array], \"5\", \"---- struct filter ----\\nschema: general_meta\\ncols: year_of_release\\ncols: factory, year_of_release,  with_demo\\n----\") called at \/path\/inc\/parserutils.php:700",
          "syntax_plugin_struct_filter->render(\"xhtml\", [Object Doku_Renderer_xhtml], [Array]) called at \/path\/inc\/parser\/renderer.php:119",
          "dokuwiki\\plugin\\struct\\meta\\Aggregation->__construct(\"search:model_result\", \"xhtml\", [Object Doku_Renderer_xhtml], [Object dokuwiki\\plugin\\struct\\meta\\SearchConfig]) called at \/path\/lib\/plugins\/struct\/syntax\/filter.php:39",
          "dokuwiki\\plugin\\struct\\meta\\Search->execute() called at \/path\/lib\/plugins\/struct\/meta\/Aggregation.php:65",
          "dokuwiki\\plugin\\sqlite\\SQLiteDB->query(\" SELECT data_general_meta.rid AS rid,\\ndata_general_meta.pid AS PID,\\ndata_general_meta.rev AS rev,\\nschema_assignments.assigned AS ASSIGNED,\\ndata_general_meta.col3 AS C0,\\ndata_general_meta.col1 AS C1,\\ndata_general_meta.col4 AS C2\\n   FROM \\ndata_general_meta AS data_general_meta\\nLEFT OUTER JOIN schema_assignments AS schema_assignments ON data_general_meta.pid != ''\\n                    AND data_general_meta.pid = schema_assignments.pid\\n                    AND schema_assignments.tbl = 'general_meta'\\n  WHERE  ( ( data_general_meta.pid = '' OR ( GETACCESSLEVEL(data_general_meta.pid) > 0 AND PAGEEXISTS(data_general_meta.pid) = 1 AND (data_general_meta.rid != 0 OR (ASSIGNED = 1 OR ASSIGNED IS NULL)) ) ) AND ( (IS_PUBLISHER(data_general_meta.pid) AND data_general_meta.latest = 1) OR (IS_PUBLISHER(data_general_meta.pid) !=1 AND data_general_meta.published = 1) ) )\\nGROUP BY data_general_meta.pid,\\ndata_general_meta.rid,\\nC0,\\nC1,\\nC2\\n\", [Array]) called at \/path\/lib\/plugins\/struct\/meta\/Search.php:457"
      ]
  }

[annda]

Thanks for all the additional info. But even with your database, I could not reproduce any of the problems on a local machine. Of course it has more resources than your hosted machine, but still the queries should not be slow. Around 4 seconds is excessive.

There is also the first error you report in io.php. The code causing problems deletes directories recursively, which has nothing to do with the database. I suspect that your disk is (very) slow and some processes get terminated before completion. If this happens during database operations, it is only natural that the database remains locked, because the process was killed that would unlock the database. In that case we cannot do anything.

Can you find out more about the physical disk storage and the I/O limit? How is it measured and set? Which processes are killed when the limit is reached?

[dgy18787]

Hello Annda and thank you for your reply. I'm now still checking this problem and seems I have partially found how it was triggered:

Can you find out more about the physical disk storage and the I/O limit? How is it measured and set? Which processes are killed when the limit is reached?

My dokuwiki is running on a virtual host, and all operations are done via cpanel. Here are the resource limits of my host:

• I/O Usage 2MB/s
• Physical Memory Usage 2GB
• Disk 9.77GB
• Number of Processes 150
• IOPS 1024
• MySQL Disk Usage depends on the free space of the host

I just checked the whole host for the problem and found that there is a huge log file on the server connection. I've downloaded the file and found that a struct filter/aggregation page (https://demodb.org/songs/sort\\\_by, remove the '\\') was requested frequently by numerous clients. They seem to find all options, and try to request all of them one by one -- I tried to block the URL that they are requesting, and it didn't take a long time, the I/O Usage has decreased significantly, and when I recover the page, the IO increased right away, which means those requests are flooding my host. I think this explains why my server was slow as a turtle every time I enabled the struct. I have added the Disallow line in robots.txt, trying to make spiders stop crawling on this page. I guess maybe struct needs a captcha feature to protect the filter/aggregation page from being flooding.

The request flooding my site is like this:

[18/Dec/2023:20:08:19 +0800] "GET /songs/sort_by?flt%5Bsong_meta.song_name_zh%3D%5D=%E6%B0%B8%E8%BF%9C%E5%9C%A8%E4%B8%80%E8%B5%B7&flt%5Bsong_meta.original_date%3D%5D=1976&flt%5Bsong_meta.composer%3D%5D=Eric%20Alfred%20Leslie%20Satie&flt%5Bsong_meta.song_name_en%3D%5D=Yesterday HTTP/1.1" 200 10343 "/songs/sort_by?flt%5Bsong_meta.song_name_zh%3D%5D=%E6%B0%B8%E8%BF%9C%E5%9C%A8%E4%B8%80%E8%B5%B7&flt%5Bsong_meta.original_date%3D%5D=1976&flt%5Bsong_meta.composer%3D%5D=Eric%20Alfred%20Leslie%20Satie&flt%5Bsong_meta.song_name_en%3D%5D=Op.20" "Mozilla/5.0 (Linux; Android 7.1.1; OPPO R9sk Build/NMF26F) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4451.57 Mobile Safari/537.36 OPR/53.0.2569.141117"

And there's another thing I noticed for the database lock: I suspected the changes in table structure might be one of the conditions. After the main update of SQLite in July, the struct plugin on my site seems not working very smoothly -- my database failed to query at first, then the dbversion often changes to 0, luckily those problems are solved in the following updates. I guess my database was not 'upgraded' properly with the plugin, and I have checked my struct database table by table and found that there is a 'chksum' column in the schemas table, but in my original database, it does not exist. So I tried to delete the struct.sqlite3 in the meta folder, rebuild the database using the SQL file dumped from the latest file, and INSERT the items one by one. After I've done this, the DokuWiki seems to be working fine, and the database is not locked so far (for 24 hours) even the spiders are flooding my aggregation page.

But there is still a thing that confuses me, I think there should be no writing action when the filter/aggregation page is being flooded, so theoretically numerous requests on the filter/aggregation page should only make the site slow response, it shouldn't end up in a locked database. I don't know if there any high-load action in the struct's design would cause that. However the problem seems to be solved temporarily, I'll keep tracking this issue on my site, and report it to you if it occurs again. Thank you for your attention!