{"action":"created","issue":{"url":"https://api.github.com/repos/SBFspot/SBFspot/issues/119","repository_url":"https://api.github.com/repos/SBFspot/SBFspot","labels_url":"https://api.github.com/repos/SBFspot/SBFspot/issues/119/labels{/name}","comments_url":"https://api.github.com/repos/SBFspot/SBFspot/issues/119/comments","events_url":"https://api.github.com/repos/SBFspot/SBFspot/issues/119/events","html_url":"https://github.com/SBFspot/SBFspot/issues/119","id":271195382,"number":119,"title":"lots of \"exec_query: database is locked\" messages","user":{"login":"SBFspot","id":32780911,"avatar_url":"https://avatars2.githubusercontent.com/u/32780911?v=4","gravatar_id":"","url":"https://api.github.com/users/SBFspot","html_url":"https://github.com/SBFspot","followers_url":"https://api.github.com/users/SBFspot/followers","following_url":"https://api.github.com/users/SBFspot/following{/other_user}","gists_url":"https://api.github.com/users/SBFspot/gists{/gist_id}","starred_url":"https://api.github.com/users/SBFspot/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/SBFspot/subscriptions","organizations_url":"https://api.github.com/users/SBFspot/orgs","repos_url":"https://api.github.com/users/SBFspot/repos","events_url":"https://api.github.com/users/SBFspot/events{/privacy}","received_events_url":"https://api.github.com/users/SBFspot/received_events","type":"User","site_admin":false},"labels":[{"id":740400781,"url":"https://api.github.com/repos/SBFspot/SBFspot/labels/CodePlexMigrationInitiated","name":"CodePlexMigrationInitiated","color":"ededed","default":false},{"id":740400782,"url":"https://api.github.com/repos/SBFspot/SBFspot/labels/Impact:%20Unassigned","name":"Impact: Unassigned","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":6,"created_at":"2017-11-04T14:17:59Z","updated_at":"2017-11-04T14:19:55Z","closed_at":null,"author_association":"OWNER","body":"I've been seeing lots of \"exec_query: database is locked\" messages from SBFspot, running on Linux with sqlite-3.6.20-1.el6.x86_64.  This causes data points to not be inserted into the database, AFAICS.\nError: exec_query() returned : database is locked\nExecuted Statement: UPDATE Inverters SET Name='SB 3000TL-US-22 100',Type='SB\n+3000TLUS-22',SW_Version='02.61.31.R' WHERE Serial=1234567800\n\nI'm running two separate inverters, each with their own .cfg file, but they are run sequentially and it looks like this is caused by SBFspotUploadDaemon accessing the SBFspot.db file at the same time.\r\n\nI've made a small patch to have the exec_query() code retry the operation several times before reporting an error, which seems to have fixed most of the problems.  There are still occasional complaints from a few code paths that don't use exec_query() but my SQL knowledge isn't good enough to know if I can resubmit those queries (e.g. day_data, event_data), and they don't happen nearly as often.\r\n\nA small patch against 3.0.7 is attached.\n\r\n\r\n#### Attachments\r\n[SBFspot-retry.diff](https://www.codeplex.com/Download/AttachmentDownload.ashx?ProjectName=SBFspot&WorkItemId=114&FileAttachmentId=1461717)\r\n[SBFspot-retry-v2.diff](https://www.codeplex.com/Download/AttachmentDownload.ashx?ProjectName=SBFspot&WorkItemId=114&FileAttachmentId=1461738)\r\n[SBFspot-retry-v3.diff](https://www.codeplex.com/Download/AttachmentDownload.ashx?ProjectName=SBFspot&WorkItemId=114&FileAttachmentId=1465760)\r\n\r\n#### This work item was migrated from CodePlex\r\nCodePlex work item ID: '114'\r\nVote count: '3'\r\n"},"comment":{"url":"https://api.github.com/repos/SBFspot/SBFspot/issues/comments/341900459","html_url":"https://github.com/SBFspot/SBFspot/issues/119#issuecomment-341900459","issue_url":"https://api.github.com/repos/SBFspot/SBFspot/issues/119","id":341900459,"user":{"login":"SBFspot","id":32780911,"avatar_url":"https://avatars2.githubusercontent.com/u/32780911?v=4","gravatar_id":"","url":"https://api.github.com/users/SBFspot","html_url":"https://github.com/SBFspot","followers_url":"https://api.github.com/users/SBFspot/followers","following_url":"https://api.github.com/users/SBFspot/following{/other_user}","gists_url":"https://api.github.com/users/SBFspot/gists{/gist_id}","starred_url":"https://api.github.com/users/SBFspot/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/SBFspot/subscriptions","organizations_url":"https://api.github.com/users/SBFspot/orgs","repos_url":"https://api.github.com/users/SBFspot/repos","events_url":"https://api.github.com/users/SBFspot/events{/privacy}","received_events_url":"https://api.github.com/users/SBFspot/received_events","type":"User","site_admin":false},"created_at":"2017-11-04T14:19:55Z","updated_at":"2017-11-04T14:19:55Z","author_association":"OWNER","body":"[LustreOne@1/07/2015]\r\nI tried the \"PRAGMA integrity_check\" on both my new database and the old one and they were both \"ok\".  Then I tried the \".dump\" command to copy the old database contents into the new one, which appeared to work (the new database grew in size to match the old one, about 2.5MB).  The next time SBFspotUploadDaemon woke up it was consuming 100% of one CPU and reading the whole database (looking for new records, I guess).  I didn't start strace on it immediately, but the IO activity looks like:\n\n```\nbrk(0x201b000)                          = 0x201b000\nlseek(4, 261120, SEEK_SET)              = 261120\nread(4, \"\\r\\0\\0\\0\\r\\0^\\0\\3\\270\\3q\\3)\\2\\342\\2\\232\\2S\\2\\v\\1\\304\\1|\\0015\\0\\355\\0\\246\"..., 1024) = 1024\nlseek(4, 262144, SEEK_SET)              = 262144\nread(4, \"\\r\\0\\0\\0\\r\\0_\\0\\3\\271\\3q\\3*\\2\\342\\2\\233\\2S\\2\\f\\1\\304\\1}\\0015\\0\\356\\0\\246\"..., 1024) = 1024\nlseek(4, 263168, SEEK_SET)              = 263168\nread(4, \"\\r\\0\\0\\0\\r\\0`\\0\\3\\270\\3q\\3)\\2\\343\\2\\233\\2T\\2\\f\\1\\305\\1}\\0017\\0\\357\\0\\250\"..., 1024) = 1024\n```\nAfter reading the database for a minute or two it opens some temporary files and starts writing into them:\n```\nstat(\"/var/tmp\", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) = 0\naccess(\"/var/tmp\", R_OK|W_OK|X_OK)      = 0\naccess(\"/var/tmp/etilqs_lJ0y1ay61p4TpcN\", F_OK) = -1 ENOENT (No such file or directory)\nopen(\"/var/tmp/etilqs_lJ0y1ay61p4TpcN\", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 8\nunlink(\"/var/tmp/etilqs_lJ0y1ay61p4TpcN\") = 0\nfcntl(8, F_GETFD)                       = 0\nfcntl(8, F_SETFD, FD_CLOEXEC)           = 0\nlseek(8, 2048, SEEK_SET)                = 2048\nwrite(8, \"\\n\\0\\0\\0\\10\\0:\\0\\0:\\0\\262\\1*\\1\\243\\2\\34\\2\\225\\3\\16\\3\\207\\0\\0\\0\\0\\0\\0\\0\\0\"..., 1024) = 1024\nlseek(4, 264192, SEEK_SET)              = 264192\nread(4, \"\\r\\0\\0\\0\\r\\0a\\0\\3\\271\\3q\\3+\\2\\343\\2\\234\\2T\\2\\r\\1\\305\\1\\177\\0017\\0\\357\\0\\250\"..., 1024) = 1024\nlseek(8, 3072, SEEK_SET)                = 3072\nwrite(8, \"\\n\\0\\0\\0\\7\\0\\261\\0\\0\\261\\1*\\1\\243\\2\\34\\2\\225\\3\\16\\3\\207\\3\\207\\0\\0\\0\\0\\0\\0\\0\\0\"..., 1024) = 1024\n```\n\nThere are five temporary files in total, in addition to the original database:\n```\n$ ls -l /proc/4615/fd\n:\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 3 -> /var/lib/smadata/SBFspot.db\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 4 -> /var/tmp/etilqs_sasQnOVaNM7vS1p (deleted)\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 5 -> /var/tmp/etilqs_sIGPlyfKXztpgWD (deleted)\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 6 -> /var/tmp/etilqs_c2wwYzquer9l5De (deleted)\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 7 -> /var/tmp/etilqs_q7yCTDiBK9dWSld (deleted)\n0 lrwx------ 1 smadata smadata 64 2015-06-30 13:00 8 -> /var/tmp/etilqs_lJ0y1ay61p4TpcN (deleted)\n```\n\nI don't know if this is because SQLite is doing a query that it thinks is too large to fit into RAM so it is writing the results into a temporary database, or if it is trying to optimize the database, or something else, but it takes much longer than the 5-minute interval between datapoints, which time out even with the added retries.\n\nI tried reverting to the new (small) database and running strace on SBFspotUploadDaemon across a full sleep-scan-sleep cycle, and it appears that this behaviour of creating and writing to the temporary files is the same, but it doesn't cause any problems because the database size is small enough that it finishes in about 20s.  The storage on this system is fast enough - an Intel SSD, but SBFspotUploadDaemon keeps one CPU core (Intel Atom 1.6GHz) 100% busy during this time.  The ltrace -c summary of calls looks like:\n```\n% time     seconds  usecs/call     calls      function\n------ ----------- ----------- --------- --------------------\n 59.16   25.771030     3221378         8 sqlite3_step\n 22.96   10.001447     5000723         2 sleep\n 10.93    4.763013     2381506         2 curl_easy_perform\n  4.77    2.076748       38458        54 _ZStlsISt11char_traitsIcEERSt13basic_ostreamIcT_ES5_PKc\n  0.69    0.300742      150371         2 sqlite3_exec\n  0.31    0.135706       33926         4 sqlite3_prepare_v2\n  0.13    0.055339         666        83 _ZNSsD1Ev\n  0.11    0.047569        1251        38 memcpy\n  [snip]\n```\n\nso it looks like the vast majority of time is spent in sqlite3_step() (the sleep() calls don't consume any CPU, I changed the loop of sleep(1) to longer sleep(60) calls).\n```\n1435740099.568808 sleep(60)                      = 0\n1435740159.575501 sqlite3_open_v2(0x22a2218, 0x7fff70076050, 2, 0, 0x7fff70076080) = 0\n1435740159.590123 curl_global_init(3, 1, 30, 0x36abaf42c0, 0x22b1290) = 0\n1435740159.590860 curl_easy_init(0x7fff70075860, 0x281959, 791, 133600, -1) = 0x22b3100\n1435740159.599402 curl_slist_append(0, 0x22bc038, 0x22bc038, 0x36abaf42c0, 0x3330343633203a64) = 0x22bc060\n1435740159.601438 curl_slist_append(0x22bc060, 0x22bc0c8, 0x22bc0c8, 0x36abaf42c0, 0x3662326636613839) = 0x22bc060\n1435740159.604004 time(NULL)                     = 1435740159\n1435740159.613062 sqlite3_prepare_v2(0x22a38b8, 0x22bc0c8, 0xffffffff, 0x7fff70075b68, 0) = 0\n1435740159.619491 sqlite3_step(0x22bc428, 0, 0, 0x36a4777ea8, 0x3c7588e0f8) = 100\n1435740159.621014 sqlite3_column_text(0x22bc428, 0, 0x22a3be8, 0, 0x22bc428) = 0x22b0fb8\n1435740159.621974 sqlite3_step(0x22bc428, 0x22b0fc2, 0, 0x3834393634373533, 10) = 101\n1435740159.622585 sqlite3_finalize(0x22bc428, 0, 0x22a3be8, 0, 0x3c7588e0c0) = 0\n1435740159.648381 sqlite3_prepare_v2(0x22a38b8, 0x22c27f8, 0xffffffff, 0x7fff70075b58, 0) = 0\n1435740159.659917 sqlite3_step(0x22bfc68, 6, 0x36abaf32d0, 6, 0x36abaf32d0) = 101\n1435740171.147830 sqlite3_finalize(0x22bfc68, 0, 0x22a3be8, 0, 0x3c7588e0c0) = 0\n1435740171.151984 curl_slist_free_all(0x22bc060, 0, 104, 0x36abaed2e0, 0x3c7588e0f8) = 0x22bc050\n1435740171.152484 curl_easy_cleanup(0x22b3100, 0x22bc050, 0x22bc050, 0x36a4777e88, 0x3c7588e0f8) = 0\n1435740171.152997 curl_global_cleanup(0x36a4777e80, 0, 0x22a2fc0, 896, 0) = 625\n1435740171.164116 curl_global_init(3, 1, 30, 0x36abaf42c0, 0x22a2e70) = 0\n1435740171.164628 curl_easy_init(0x7fff70075860, 0x281959, 958, 134384, -1) = 0x22b3100\n1435740171.171126 curl_slist_append(0, 0x22d8ea8, 0x22d8ea8, 0x36abaf42c0, 0x3230343633203a64) = 0x22a31c0\n1435740171.173010 curl_slist_append(0x22a31c0, 0x22d7cf8, 0x22d7cf8, 0x36abaf42c0, 0x3662326636613839) = 0x22a31c0\n1435740171.175457 time(NULL)                     = 1435740171\n1435740171.185899 sqlite3_prepare_v2(0x22a38b8, 0x22d7cf8, 0xffffffff, 0x7fff70075b68, 0) = 0\n1435740171.187288 sqlite3_step(0x22d87a8, 0, 0, 0x36a4777ea8, 0x3c7588e0f8) = 100\n1435740171.188803 sqlite3_column_text(0x22d87a8, 0, 0x22a3be8, 0, 0x22d87a8) = 0x22a4be8\n1435740171.189748 sqlite3_step(0x22d87a8, 0x22a4bf2, 0, 0x3834393634373533, 10) = 101\n1435740171.190332 sqlite3_finalize(0x22d87a8, 0, 0x22a3be8, 0, 0x3c7588e0c0) = 0\n1435740171.206447 sqlite3_prepare_v2(0x22a38b8, 0x22c27f8, 0xffffffff, 0x7fff70075b58, 0) = 0\n1435740171.209096 sqlite3_step(0x22bd0d8, 6, 0x36abaf32d0, 6, 0x36abaf32d0) = 101\n1435740181.720903 sqlite3_finalize(0x22bd0d8, 0, 0x22a3be8, 0, 0x3c7588e0c0) = 0\n1435740181.723328 curl_slist_free_all(0x22a31c0, 0, 104, 0x36abaed2e0, 0x3c7588e0f8) = 0x22a31b0\n1435740181.723787 curl_easy_cleanup(0x22b3100, 0x22a31b0, 0x22a31b0, 0x36a4777e88, 0x3c7588e0f8) = 0\n1435740181.724278 curl_global_cleanup(0x36a4777e80, 0, 0x22d7e60, 896, 0) = 849\n1435740181.729995 sqlite3_close(0x22a38b8, 0x7fff700760c0, 0x624d70, 0x22a47a0, 0x22d8fd0) = 0\n1435740181.731981 sleep(60)                      = 0\n```\n\nI don't really know much about sqlite so I can't really comment on what that code is doing.\r\n\r\n"}}
{"actor":{"display_login":"SBFspot"}}