作成者 |
メッセージ |
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
EarlgreyTea さんが書きました: ちなみにこのエラーはGoogleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生しました。 ここで言う「エラー」は、 00182974 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'BEGIN DEFERRED' 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' ですよね。 そして、ツールバーボタンでチェックしようとしたら、 [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] NS_ERROR_STORAGE_BUSY: button.js:62:0 となって、 getLocalStorageForPrincipal() の時点でNS_ERROR_STORAGE_BUSYが発生した。 https://twitter.com:443 のスコープで、 sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' Statement::ExecuteStep error: database is locked sqlite3_trace on 2050d640 for 'ROLLBACK' が起こったことと、 biscuit_deltaというTableで 'DELETE FROM biscuit_delta WHERE rowid=1'が起こったこととは、 直接の関係はないでしょう。 Googleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生した、というのは、それ以前に既にロックがリリースされない問題が起こっていて、 タブグループをカレントに切り替えた際に、 Table-webappsstore2,scope=moc.rettiwt.:https:443,key=__connect_badge__:keep_badge_until、の更新が起こり、 そこで、既に起こっている問題のせいで、'ExecuteStep error: database is lockedが返り、ROLLBACKがだされた、ということだと思います。 scope=moc.rettiwt.:https:443は、既に起こっている「ロックがリリースされない問題」の被害者であるだけ、という可能性もあります。 「ROLLBACKの後できちんとリクエストが再試行されて再実行されている」ということが確認できない、ということが、問題が起こる前におこっているかどうかを見ないと、どのあたりで問題が起こったのかを調べるのは難しいでしょう。 Table-webappsstore2,scope=moc.rettiwt.:https:443,key=__connect_badge__:keep_badge_until、の更新でSQLITE_BUSYが返り、それによって出されたROLLBACKでもSQLITE_BUSYが返って、ROLLBACKの無限リトライ、の可能性も、十分にありますけど、 ROLLBACKに対してSQLITE_BUSYが返り続けることの原因は、もっと以前に作り出されていると思います。 いずれにせよ、 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' が起こり、 その後、http://ja.wikipedia.org:80のスコープの新規のアクセスができない、 ということが、極く普通にLocalStorageを更新しているだけで起こった、 というのは確実です。 ロジックでは、ROLLBACKではSQLITE_BUSYが返ってこなくなるまで無限リトライ、SQLITE_ABORTもSQLITE_ABORT_ROLLBACKも無視、ですから、現時点では何が起こっても不思議ではない状態なんでしょうね。
[quote="EarlgreyTea"]ちなみにこのエラーはGoogleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生しました。[/quote]ここで言う「エラー」は、 00182974 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'BEGIN DEFERRED' 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' ですよね。 そして、ツールバーボタンでチェックしようとしたら、 [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] NS_ERROR_STORAGE_BUSY: button.js:62:0 となって、 getLocalStorageForPrincipal() の時点でNS_ERROR_STORAGE_BUSYが発生した。
https://twitter.com:443 のスコープで、 sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' Statement::ExecuteStep error: database is locked sqlite3_trace on 2050d640 for 'ROLLBACK' が起こったことと、 biscuit_deltaというTableで 'DELETE FROM biscuit_delta WHERE rowid=1'が起こったこととは、 直接の関係はないでしょう。
Googleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生した、というのは、それ以前に既にロックがリリースされない問題が起こっていて、 タブグループをカレントに切り替えた際に、 Table-webappsstore2,scope=moc.rettiwt.:https:443,key=__connect_badge__:keep_badge_until、の更新が起こり、 そこで、既に起こっている問題のせいで、'ExecuteStep error: database is lockedが返り、ROLLBACKがだされた、ということだと思います。
scope=moc.rettiwt.:https:443は、既に起こっている「ロックがリリースされない問題」の被害者であるだけ、という可能性もあります。 「ROLLBACKの後できちんとリクエストが再試行されて再実行されている」ということが確認できない、ということが、問題が起こる前におこっているかどうかを見ないと、どのあたりで問題が起こったのかを調べるのは難しいでしょう。 Table-webappsstore2,scope=moc.rettiwt.:https:443,key=__connect_badge__:keep_badge_until、の更新でSQLITE_BUSYが返り、それによって出されたROLLBACKでもSQLITE_BUSYが返って、ROLLBACKの無限リトライ、の可能性も、十分にありますけど、 ROLLBACKに対してSQLITE_BUSYが返り続けることの原因は、もっと以前に作り出されていると思います。
いずれにせよ、 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' が起こり、 その後、http://ja.wikipedia.org:80のスコープの新規のアクセスができない、 ということが、極く普通にLocalStorageを更新しているだけで起こった、 というのは確実です。 ロジックでは、ROLLBACKではSQLITE_BUSYが返ってこなくなるまで無限リトライ、SQLITE_ABORTもSQLITE_ABORT_ROLLBACKも無視、ですから、現時点では何が起こっても不思議ではない状態なんでしょうね。
|
|
|
|
Posted: 2015年4月07日(火) 11:58 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
WADAさんに教えていただいたCustom ButtonsとDebugViewを準備し、通常使用していてエラー発生した際のNPSRログ(常時キャプチャ&ログ書き出し)を取りました。 前回の事例ではchaikaのgrayスキンが履歴を更新する際のエラーでしたが、今回は https://twitter.com:443 スコープで先にエラーになった事例です。 コード: 00182970 14:59:19.080 [4424] 0[2711140]: Initialized statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' (0x20da7300) 00182971 14:59:19.080 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' 00182972 14:59:19.080 [4424] 0[2711140]: Initialized statement 'DELETE FROM biscuit_delta WHERE rowid=:rowid' (0x216431f0) 00182973 14:59:19.080 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'DELETE FROM biscuit_delta WHERE rowid=1' 00182974 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'BEGIN DEFERRED' 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' 00182978 14:59:19.253 [4424] 0[2711140]: Finalizing statement 'DELETE FROM biscuit_delta WHERE rowid=:rowid' during garbage-collection 00182979 14:59:19.254 [4424] 0[2711140]: Finalizing statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' during garbage-collection 00182980 14:59:19.764 [4424] 0[2711140]: Initialized statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' (0x224799d0) 00182981 14:59:19.764 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' 00182982 14:59:19.764 [4424] 0[2711140]: Finalizing statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' during garbage-collection
どうやら、[2711140]の Initialized statement ... Finalizing statement の間に[2043b8e0]が割り込んだ形になってるようです。 この状態のまま、Custom Buttonsのボタンからスクリプトを走らせてテストを行いました。以下がそのスクリプトです。 コード: // LocalStorageに保存された各スコープの全項目の読み出し/書き込みテスト
var consrv = Components.classes["@mozilla.org/consoleservice;1"] .getService(Components.interfaces.nsIConsoleService); var prefix = "[TestLocalStorageAll]"; var enableFirebug = !(typeof Firebug == "undefined") && !(typeof Firebug.Console == "undefined");
function dbglog(message) { var msg = prefix + message; consrv.logStringMessage(msg); enableFirebug && Firebug.Console.log(msg); }
var ios = Components.classes["@mozilla.org/network/io-service;1"] .getService(Components.interfaces.nsIIOService); var ssm = Components.classes["@mozilla.org/scriptsecuritymanager;1"] .getService(Components.interfaces.nsIScriptSecurityManager); var dsm = Components.classes["@mozilla.org/dom/storagemanager;1"] .getService(Components.interfaces.nsIDOMStorageManager);
var site = new Array( "http://ja.wikipedia.org:80", "http://127.0.0.1:8823", /* ... */ "https://www.youtube.com:443" );
for(s = 0; s < site.length; s++){ var scope = site[s]; dbglog(scope);
try { var uri = ios.newURI(scope, "", null); } catch(e) { dbglog(e); } dbglog(uri); try { var principal = ssm.getCodebasePrincipal(uri); } catch(e) { dbglog(e); } dbglog(principal); try { var ls = dsm.getLocalStorageForPrincipal(principal, ""); } catch(e) { dbglog(e); } dbglog(ls); for(n = 0; n < ls.length; n++){ var Key=ls.key(n); dbglog(" "+Key); try{ ls.setItem(Key, ls.getItem(Key)); } catch(e){ dbglog("scope=" + scope + " key=" + Key + " e=" + e); } } }
dbglog("complete"); alert("complete");
一部省略してますが、配列siteには事前にFirebugのFireStorage Plus!パネルで調べた全サイトをセットしておきます。 ブラウザコンソールを開いておくと正常時は、 コード: [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] MediaWikiModuleStore:jawiki [TestLocalStorageAll] CentralAuthAnon [TestLocalStorageAll]http://127.0.0.1:8823 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] pref-delay-popup [TestLocalStorageAll] pref-enable-non-strict-image-detection [TestLocalStorageAll] smorgasbord_valueHistoryManager [TestLocalStorageAll] skin.gray2x [TestLocalStorageAll] smorgasbord_nameSkinStyle [TestLocalStorageAll] pref-max-posts-in-popup ... [TestLocalStorageAll]https://www.youtube.com:443 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] yt-player-volume [TestLocalStorageAll] yt-remote-device-id [TestLocalStorageAll] yt-player-two-stage-token [TestLocalStorageAll] yt-remote-online-screens [TestLocalStorageAll] yt.autonav::autonav_disabled [TestLocalStorageAll] yt-remote-connected-devices [TestLocalStorageAll]complete
となるところ、 コード: [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] NS_ERROR_STORAGE_BUSY: button.js:62:0
で終了しました。getLocalStorageForPrincipal() の時点でNS_ERROR_STORAGE_BUSYが発生しているようです。 一方、NSPRログは正常時は、 コード: 00000555 20:28:32.777 [5548] 35776[1ed67190]: sqlite3_trace on 203c9100 for 'SELECT key, value FROM webappsstore2 WHERE scope = 'gro.aidepikiw.aj.:http:80' ORDER BY key LIMIT -1 OFFSET 0' 00000556 20:28:32.777 [5548] 0[2b11140]: Initialized statement 'SELECT key, value FROM webappsstore2 WHERE scope = :scope ORDER BY key LIMIT -1 OFFSET :offset' (0xe6bbef0) 00000557 20:28:32.778 [5548] 0[2b11140]: sqlite3_trace on 1cc51100 for 'SELECT key, value FROM webappsstore2 WHERE scope = 'gro.aidepikiw.aj.:http:80' ORDER BY key LIMIT -1 OFFSET 1' 00000558 20:28:32.778 [5548] 35776[1ed67190]: sqlite3_trace on 203c9100 for 'SELECT SUM(LENGTH(key) + LENGTH(value)) FROM webappsstore2 WHERE scope LIKE 'gro.aidepikiw.%''
といった具合に出力されますが、例外が出てスクリプト終了しているのでログには残っていません。 ちなみにこのエラーはGoogleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生しました。 【余談】 ブラウザーコンソールを開いていると拡張機能やWEBアプリが頻繁に未定義変数参照のTypeErrorを吐き続けるし、何より新規プロファイルであっても起動時に必ず コード: Could not read chrome manifest 'file:///C:/Program%20Files%20(x86)/Mozilla%20Firefox/chrome.manifest'. Could not read chrome manifest 'file:///C:/Program%20Files%20(x86)/Mozilla%20Firefox/browser/extensions/%7B972ce4c6-7e08-4474-a285-3208198ce6fd%7D/chrome.manifest'. を出してくるのが気になります。 ちょっとググってみたら、 Bug 586610 というのが見つかったけど初出が2010-08-12。 悪さはしないけど正常時のログはスッキリしてて欲しいなと思ったり。
WADAさんに教えていただいたCustom ButtonsとDebugViewを準備し、通常使用していてエラー発生した際のNPSRログ(常時キャプチャ&ログ書き出し)を取りました。 前回の事例ではchaikaのgrayスキンが履歴を更新する際のエラーでしたが、今回は https://twitter.com:443 スコープで先にエラーになった事例です。 [code] 00182970 14:59:19.080 [4424] 0[2711140]: Initialized statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' (0x20da7300) 00182971 14:59:19.080 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' 00182972 14:59:19.080 [4424] 0[2711140]: Initialized statement 'DELETE FROM biscuit_delta WHERE rowid=:rowid' (0x216431f0) 00182973 14:59:19.080 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'DELETE FROM biscuit_delta WHERE rowid=1' 00182974 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'BEGIN DEFERRED' 00182975 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('moc.rettiwt.:https:443', '__connect_badge__:keep_badge_until', '{"until":1427263155109}') ' 00182976 14:59:19.133 [4424] 2480[2043b8e0]: Statement::ExecuteStep error: database is locked 00182977 14:59:19.133 [4424] 2480[2043b8e0]: sqlite3_trace on 2050d640 for 'ROLLBACK' 00182978 14:59:19.253 [4424] 0[2711140]: Finalizing statement 'DELETE FROM biscuit_delta WHERE rowid=:rowid' during garbage-collection 00182979 14:59:19.254 [4424] 0[2711140]: Finalizing statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' during garbage-collection 00182980 14:59:19.764 [4424] 0[2711140]: Initialized statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' (0x224799d0) 00182981 14:59:19.764 [4424] 0[2711140]: sqlite3_trace on e0b1460 for 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' 00182982 14:59:19.764 [4424] 0[2711140]: Finalizing statement 'SELECT rowid,biscuitLsnr(action,scope,key,value,secure,owner) FROM biscuit_delta' during garbage-collection [/code]どうやら、[2711140]の Initialized statement ... Finalizing statement の間に[2043b8e0]が割り込んだ形になってるようです。
この状態のまま、Custom Buttonsのボタンからスクリプトを走らせてテストを行いました。以下がそのスクリプトです。 [code] // LocalStorageに保存された各スコープの全項目の読み出し/書き込みテスト
var consrv = Components.classes["@mozilla.org/consoleservice;1"] .getService(Components.interfaces.nsIConsoleService); var prefix = "[TestLocalStorageAll]"; var enableFirebug = !(typeof Firebug == "undefined") && !(typeof Firebug.Console == "undefined");
function dbglog(message) { var msg = prefix + message; consrv.logStringMessage(msg); enableFirebug && Firebug.Console.log(msg); }
var ios = Components.classes["@mozilla.org/network/io-service;1"] .getService(Components.interfaces.nsIIOService); var ssm = Components.classes["@mozilla.org/scriptsecuritymanager;1"] .getService(Components.interfaces.nsIScriptSecurityManager); var dsm = Components.classes["@mozilla.org/dom/storagemanager;1"] .getService(Components.interfaces.nsIDOMStorageManager);
var site = new Array( "http://ja.wikipedia.org:80", "http://127.0.0.1:8823", /* ... */ "https://www.youtube.com:443" );
for(s = 0; s < site.length; s++){ var scope = site[s]; dbglog(scope);
try { var uri = ios.newURI(scope, "", null); } catch(e) { dbglog(e); } dbglog(uri); try { var principal = ssm.getCodebasePrincipal(uri); } catch(e) { dbglog(e); } dbglog(principal); try { var ls = dsm.getLocalStorageForPrincipal(principal, ""); } catch(e) { dbglog(e); } dbglog(ls); for(n = 0; n < ls.length; n++){ var Key=ls.key(n); dbglog(" "+Key); try{ ls.setItem(Key, ls.getItem(Key)); } catch(e){ dbglog("scope=" + scope + " key=" + Key + " e=" + e); } } }
dbglog("complete"); alert("complete"); [/code] 一部省略してますが、配列siteには事前にFirebugのFireStorage Plus!パネルで調べた全サイトをセットしておきます。 ブラウザコンソールを開いておくと正常時は、 [code] [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] MediaWikiModuleStore:jawiki [TestLocalStorageAll] CentralAuthAnon [TestLocalStorageAll]http://127.0.0.1:8823 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] pref-delay-popup [TestLocalStorageAll] pref-enable-non-strict-image-detection [TestLocalStorageAll] smorgasbord_valueHistoryManager [TestLocalStorageAll] skin.gray2x [TestLocalStorageAll] smorgasbord_nameSkinStyle [TestLocalStorageAll] pref-max-posts-in-popup ... [TestLocalStorageAll]https://www.youtube.com:443 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] [TestLocalStorageAll][object Storage] [TestLocalStorageAll] yt-player-volume [TestLocalStorageAll] yt-remote-device-id [TestLocalStorageAll] yt-player-two-stage-token [TestLocalStorageAll] yt-remote-online-screens [TestLocalStorageAll] yt.autonav::autonav_disabled [TestLocalStorageAll] yt-remote-connected-devices [TestLocalStorageAll]complete [/code]となるところ、[code] [TestLocalStorageAll]http://ja.wikipedia.org:80 [TestLocalStorageAll][xpconnect wrapped nsIURI] [TestLocalStorageAll][xpconnect wrapped (nsISupports, nsIPrincipal, nsISerializable)] NS_ERROR_STORAGE_BUSY: button.js:62:0 [/code]で終了しました。getLocalStorageForPrincipal() の時点でNS_ERROR_STORAGE_BUSYが発生しているようです。
一方、NSPRログは正常時は、 [code] 00000555 20:28:32.777 [5548] 35776[1ed67190]: sqlite3_trace on 203c9100 for 'SELECT key, value FROM webappsstore2 WHERE scope = 'gro.aidepikiw.aj.:http:80' ORDER BY key LIMIT -1 OFFSET 0' 00000556 20:28:32.777 [5548] 0[2b11140]: Initialized statement 'SELECT key, value FROM webappsstore2 WHERE scope = :scope ORDER BY key LIMIT -1 OFFSET :offset' (0xe6bbef0) 00000557 20:28:32.778 [5548] 0[2b11140]: sqlite3_trace on 1cc51100 for 'SELECT key, value FROM webappsstore2 WHERE scope = 'gro.aidepikiw.aj.:http:80' ORDER BY key LIMIT -1 OFFSET 1' 00000558 20:28:32.778 [5548] 35776[1ed67190]: sqlite3_trace on 203c9100 for 'SELECT SUM(LENGTH(key) + LENGTH(value)) FROM webappsstore2 WHERE scope LIKE 'gro.aidepikiw.%'' [/code]といった具合に出力されますが、例外が出てスクリプト終了しているのでログには残っていません。 ちなみにこのエラーはGoogleスプレッドシートをいくつか開いておいたタブグループをカレントに切り替えた途端に発生しました。
【余談】 ブラウザーコンソールを開いていると拡張機能やWEBアプリが頻繁に未定義変数参照のTypeErrorを吐き続けるし、何より新規プロファイルであっても起動時に必ず [code] Could not read chrome manifest 'file:///C:/Program%20Files%20(x86)/Mozilla%20Firefox/chrome.manifest'. Could not read chrome manifest 'file:///C:/Program%20Files%20(x86)/Mozilla%20Firefox/browser/extensions/%7B972ce4c6-7e08-4474-a285-3208198ce6fd%7D/chrome.manifest'.[/code]を出してくるのが気になります。 ちょっとググってみたら、[url=https://bugzilla.mozilla.org/show_bug.cgi?id=671894]Bug 586610[/url] というのが見つかったけど初出が2010-08-12。 悪さはしないけど正常時のログはスッキリしてて欲しいなと思ったり。
|
|
|
|
Posted: 2015年3月26日(木) 19:54 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
chaika+grayを使っていれば、try/catchを入れているし、問題が起これば気がつくし、もう、しゃかりきになって再現させなくても良さそうな気が。 localStorageのsetItem/removeItemという、一つの行しか更新しないトランザクションの間の話ですから、同じscope内の競合、同じscope+keyの間の競合、ではなくて、別のscopeの間の行の範囲の更新のためのロックの競合、という気がします。 ならば、いくつかのツールバーボタンで、一つあるいはいくつかのscopeについて、setTimeoutでsetItem()やremoveItem()を繰り返しだしてたまにはclear()をだして、try/catchでエラーを検出しておけば、いずれどここかで、GoogleとかYahoo!とかTwitterとかのスーパーヘビーユーザーと競合して、なんらかのデータがとれそうに思います。 向こうが先に競合に勝つと、負けたこちらのROLLBACKで向こうがこけて、Google地図やYahoo!地図の一部が欠けるといった現象を引きおこせるかもしれません(^^)
これ自体は、提示したスクリプトでわかるとおり、非常に簡単。 あれは、WebサイトのHTML用のwindowコンテキストを作って、window.locakStorageというオブジェクトを作るコードをパクっただけ。 Custom Buttonsで作ったボタンは、普通にツールバーボタンですから、そこに貼り付けたスクリプトは、普通にツールバーボタンのスクリプトとして動くから、何でもできます。
chaika+grayを使っていれば、try/catchを入れているし、問題が起これば気がつくし、もう、しゃかりきになって再現させなくても良さそうな気が。 localStorageのsetItem/removeItemという、一つの行しか更新しないトランザクションの間の話ですから、同じscope内の競合、同じscope+keyの間の競合、ではなくて、別のscopeの間の行の範囲の更新のためのロックの競合、という気がします。 ならば、いくつかのツールバーボタンで、一つあるいはいくつかのscopeについて、setTimeoutでsetItem()やremoveItem()を繰り返しだしてたまにはclear()をだして、try/catchでエラーを検出しておけば、いずれどここかで、GoogleとかYahoo!とかTwitterとかのスーパーヘビーユーザーと競合して、なんらかのデータがとれそうに思います。 向こうが先に競合に勝つと、負けたこちらのROLLBACKで向こうがこけて、Google地図やYahoo!地図の一部が欠けるといった現象を引きおこせるかもしれません(^^)
これ自体は、提示したスクリプトでわかるとおり、非常に簡単。 あれは、WebサイトのHTML用のwindowコンテキストを作って、window.locakStorageというオブジェクトを作るコードをパクっただけ。 Custom Buttonsで作ったボタンは、普通にツールバーボタンですから、そこに貼り付けたスクリプトは、普通にツールバーボタンのスクリプトとして動くから、何でもできます。
|
|
|
|
Posted: 2015年3月12日(木) 13:28 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
なるべく情報提供に協力したいと思いますが、ひとまず検討させてください。再現可能なミニマム環境にもう一度トライしてみたいですね。前やった時は拡張機能しか頭になかったので。新規プロファイルにツイッター、YouTube、FoxAge2ch、chaika+grayで行けそうな気がしてます。
なるべく情報提供に協力したいと思いますが、ひとまず検討させてください。再現可能なミニマム環境にもう一度トライしてみたいですね。前やった時は拡張機能しか頭になかったので。新規プロファイルにツイッター、YouTube、FoxAge2ch、chaika+grayで行けそうな気がしてます。
|
|
|
|
Posted: 2015年3月11日(水) 22:47 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
EarlgreyTea さんは、Windowsユーザーでしたね。 それならば、DebugViewにmozStorge:5のログを書かせておき、普段はDebugViewのCaptureを止めておき、 できるだけ多くのlocalStorage.setItem()/removeItem()/clear()をtry/catchに入れておき、 localStorage.clear()などのcatch(e)でエクセプションを検出した時に、DebugViewのCaptureを開始して、 Custom Buttonsというアドオンで追加した自前のツールバーボタンで、そこで使われたscopeに対して、 コード: var LS=localStorag;for(nn=0;nn<LS.length;nn++){ var Key=LS.key(nn); try{ LS.setItem( Key, LS.getItem(Key) ); } catch(e){ ... } }
を行うと、もう少し詳しい状況がわかると思います。 DebugView : https://technet.microsoft.com/en-us/library/bb896647.aspxコード: SET NSPR_LOG_FILE=WinDebug SET NSPR_LOG_MODULES=mozStorage:5 タイムスタンプはDebugViewがつけるので、timestampは指定しない。
scopeを選択する方法。 コード: // Directly access from XUL with any URL var ios = Components.classes["@mozilla.org/network/io-service;1"] .getService(Components.interfaces.nsIIOService); var ssm = Components.classes["@mozilla.org/scriptsecuritymanager;1"] .getService(Components.interfaces.nsIScriptSecurityManager); var dsm = Components.classes["@mozilla.org/dom/storagemanager;1"] .getService(Components.interfaces.nsIDOMStorageManager); get_localStorage = function (Site) { var uri = ios.newURI(Site, "", null); var principal = ssm.getCodebasePrincipal(uri); var localStorage = dsm.getLocalStorageForPrincipal(principal, ""); return localStorage; }
// エクセプション、ログ、SQLDBの中身などから得たscopeの文字列をひっくり返して、URIにする var URI = "https://www.example.com:8080"; var localStorage=get_localStorage(URI);
EarlgreyTea さんは、Windowsユーザーでしたね。 それならば、DebugViewにmozStorge:5のログを書かせておき、普段はDebugViewのCaptureを止めておき、 できるだけ多くのlocalStorage.setItem()/removeItem()/clear()をtry/catchに入れておき、 localStorage.clear()などのcatch(e)でエクセプションを検出した時に、DebugViewのCaptureを開始して、 Custom Buttonsというアドオンで追加した自前のツールバーボタンで、そこで使われたscopeに対して、 [code] var LS=localStorag;for(nn=0;nn<LS.length;nn++){ var Key=LS.key(nn); try{ LS.setItem( Key, LS.getItem(Key) ); } catch(e){ ... } } [/code]を行うと、もう少し詳しい状況がわかると思います。
DebugView : [url=https://technet.microsoft.com/en-us/library/bb896647.aspx]https://technet.microsoft.com/en-us/library/bb896647.aspx[/url] [code] SET NSPR_LOG_FILE=WinDebug SET NSPR_LOG_MODULES=mozStorage:5 タイムスタンプはDebugViewがつけるので、timestampは指定しない。 [/code] scopeを選択する方法。 [code] // Directly access from XUL with any URL var ios = Components.classes["@mozilla.org/network/io-service;1"] .getService(Components.interfaces.nsIIOService); var ssm = Components.classes["@mozilla.org/scriptsecuritymanager;1"] .getService(Components.interfaces.nsIScriptSecurityManager); var dsm = Components.classes["@mozilla.org/dom/storagemanager;1"] .getService(Components.interfaces.nsIDOMStorageManager); get_localStorage = function (Site) { var uri = ios.newURI(Site, "", null); var principal = ssm.getCodebasePrincipal(uri); var localStorage = dsm.getLocalStorageForPrincipal(principal, ""); return localStorage; }
// エクセプション、ログ、SQLDBの中身などから得たscopeの文字列をひっくり返して、URIにする var URI = "https://www.example.com:8080"; var localStorage=get_localStorage(URI); [/code]
|
|
|
|
Posted: 2015年3月11日(水) 17:48 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
折角 mozStorage:5 を教えてもらったので、ちょっと見てみました。 - cookies.sqlite の moz_cookies
Transactionのような概念を持たず、全て単独のSQL文の実行 - places.sqlite の ブックマーク系(moz_bookmarks, moz_places, moz_favicon) :
BEGIN IMMEDIATE + 0個以上のSQL文 + COMMIT TRANSACTION - places.sqlite の ブックマーク系以外
BEGIN DEFERRED + 1個以上のSQL文 + COMMIT TRANSACTION - webappsstore2
BEGIN DEFERRED + 1個以上のSQL文 + COMMIT TRANSACTION
moz_cookiesは、1 Table のみ、一回に一行しか更新しない、各行は完全に独立、 ブックマーク系は、Table は3つだけれど、一回に各Tableの一行のみしか更新しない、 ブックマーク系以外は、複数のTableの複数の行の同時更新があり得る、 webappsstore2は、Tableは1つだけれど、複数の行の同時更新があり得る、 といったような違いによって、mozStorageの利用のしかたが異なるようです。 で、BEGIN DEFERRED/BEGIN IMMEDIATEだと、COMMITするか、COMMITできなければROLLBACK。 のはずが、COMMITできない・できていないのに、ROLLBACKをださないことがある、と。 [ちょっと訂正] ROLLBACKをださない、ではなかった。 setItem()によるInsert/Replceと他のリクエストで競合が起こった時に、 自分が勝つと、競合相手にはSQLITE_BUSYが返るので、競合相手がROLLBACKをだし、 今度は、その競合相手がだしたROLLBACKに自分のInsert/Replceが負けて、その結果SQLITE_ABORTが返ってきて、COMMITできないからROLLBACKをだすのだけれど、 それも競合相手がだしたROLLBACKに負けると、今度はROLLBACKにSQLITE_ABORT_ROLLBACKが返ってきて、 その時に、もう一度ROLLBACKをださないから、結局、ROLLBACKをだしていないのと同じになり、 最初にSQLITE_ABORTが返った時点で行のロックがとれていると、ロックがリリースされなくなる。 競争に勝った方が、負けた方のROLLBACKによって躓いて大逆転がおこり、あげくのはてに、踏みつけられてボロボロになる(^^) [/ちょっと訂正のおわり] 参考までに。
折角 mozStorage:5 を教えてもらったので、ちょっと見てみました。 [list] [*]cookies.sqlite の moz_cookies Transactionのような概念を持たず、全て単独のSQL文の実行 [*]places.sqlite の ブックマーク系(moz_bookmarks, moz_places, moz_favicon) : BEGIN IMMEDIATE + 0個以上のSQL文 + COMMIT TRANSACTION [*]places.sqlite の ブックマーク系以外 BEGIN DEFERRED + 1個以上のSQL文 + COMMIT TRANSACTION [*]webappsstore2 BEGIN DEFERRED + 1個以上のSQL文 + COMMIT TRANSACTION[/list]
moz_cookiesは、1 Table のみ、一回に一行しか更新しない、各行は完全に独立、 ブックマーク系は、Table は3つだけれど、一回に各Tableの一行のみしか更新しない、 ブックマーク系以外は、複数のTableの複数の行の同時更新があり得る、 webappsstore2は、Tableは1つだけれど、複数の行の同時更新があり得る、 といったような違いによって、mozStorageの利用のしかたが異なるようです。
で、BEGIN DEFERRED/BEGIN IMMEDIATEだと、COMMITするか、COMMITできなければROLLBACK。 のはずが、COMMITできない・できていないのに、ROLLBACKをださないことがある、と。 [ちょっと訂正] ROLLBACKをださない、ではなかった。 setItem()によるInsert/Replceと他のリクエストで競合が起こった時に、 自分が勝つと、競合相手にはSQLITE_BUSYが返るので、競合相手がROLLBACKをだし、 今度は、その競合相手がだしたROLLBACKに自分のInsert/Replceが負けて、その結果SQLITE_ABORTが返ってきて、COMMITできないからROLLBACKをだすのだけれど、 それも競合相手がだしたROLLBACKに負けると、今度はROLLBACKにSQLITE_ABORT_ROLLBACKが返ってきて、 その時に、もう一度ROLLBACKをださないから、結局、ROLLBACKをだしていないのと同じになり、 最初にSQLITE_ABORTが返った時点で行のロックがとれていると、ロックがリリースされなくなる。 競争に勝った方が、負けた方のROLLBACKによって躓いて大逆転がおこり、あげくのはてに、踏みつけられてボロボロになる(^^) [/ちょっと訂正のおわり]
参考までに。
|
|
|
|
Posted: 2015年3月08日(日) 18:14 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
ちょっと、訂正です。 コード: 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK' sqlite3_traceのログが書かれるタイミングを勘違いしていました。 setItem('skin.gray2x',...) ⇒ INSERT OR REPLACEの、sqlite3_trace ログ ⇒ INSERT OR REPLACE の実行 ⇒ SQLITE_BUSY ⇒ Statement::ExecuteStep error: database is locked のログ ⇒ ROLLBACK がだされて、ROLLBACKのsqlite3_trace ログ だと思います。 SQL文の実行 ⇒ エラーがあると、Statement::ExecuteStep error:のログ ⇒ 終了後に、sqlite3_trace ログ だと、setItem('skin.gray2x',...)によるINSERT OR REPLACEは成功しているわけで、そもそも、ROLLBACKがでること自体がおかしい。 上記のログは、ROLLBACKの後に、key='skin.gray2x'に対してもう一度INSERT OR REPLACEが実行されていれば、 単に、SQLITE_BUSYが一度返った、ということになると思います。 でも、clear()以外は一行の更新しかしないlocalStorageで、 localStorage.clear()を scope="http://www.youtube.com" で頻繁にだすはずがなく、99.99%の更新はsetItemかremoveItemしか考えられないlocalStorageで、 同じscopeの同じkeyの行を複数のタスクが同時に更新する、ということはあまり考えられないlocalStorageであっても、 SQLITE_BUSYが返った後にROLLBACKがだされることが実際に起こる、という証拠を得られたのは、大収穫です。 ROLLBACKを出すコードがあったって、そのコードがlocalStorageのアクセスで実際に呼ばれて実際にROLLBACKがでるかどうかなんて、プログラムを書いた本人だって、コードを見ただけで簡単にわかるはずがない。 setItem()からROLLBACKコールに到る長い道のりの、自分が知らないどこかにif(flag)break;があって、知らない人がいつの間にかflag=trueをセットしていた、なんてなことは、良くある話。 やっぱり、「ROLLBACKが出ていた」という、直接証拠が一番(^^)
ちょっと、訂正です。 [code]2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK'[/code] sqlite3_traceのログが書かれるタイミングを勘違いしていました。 setItem('skin.gray2x',...) ⇒ INSERT OR REPLACEの、sqlite3_trace ログ ⇒ INSERT OR REPLACE の実行 ⇒ SQLITE_BUSY ⇒ Statement::ExecuteStep error: database is locked のログ ⇒ ROLLBACK がだされて、ROLLBACKのsqlite3_trace ログ だと思います。
SQL文の実行 ⇒ エラーがあると、Statement::ExecuteStep error:のログ ⇒ 終了後に、sqlite3_trace ログ だと、setItem('skin.gray2x',...)によるINSERT OR REPLACEは成功しているわけで、そもそも、ROLLBACKがでること自体がおかしい。
上記のログは、ROLLBACKの後に、key='skin.gray2x'に対してもう一度INSERT OR REPLACEが実行されていれば、 単に、SQLITE_BUSYが一度返った、ということになると思います。
でも、clear()以外は一行の更新しかしないlocalStorageで、 localStorage.clear()を scope="http://www.youtube.com" で頻繁にだすはずがなく、99.99%の更新はsetItemかremoveItemしか考えられないlocalStorageで、 同じscopeの同じkeyの行を複数のタスクが同時に更新する、ということはあまり考えられないlocalStorageであっても、 SQLITE_BUSYが返った後にROLLBACKがだされることが実際に起こる、という証拠を得られたのは、大収穫です。 ROLLBACKを出すコードがあったって、そのコードがlocalStorageのアクセスで実際に呼ばれて実際にROLLBACKがでるかどうかなんて、プログラムを書いた本人だって、コードを見ただけで簡単にわかるはずがない。 setItem()からROLLBACKコールに到る長い道のりの、自分が知らないどこかにif(flag)break;があって、知らない人がいつの間にかflag=trueをセットしていた、なんてなことは、良くある話。 やっぱり、「ROLLBACKが出ていた」という、直接証拠が一番(^^)
|
|
|
|
Posted: 2015年3月08日(日) 17:20 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
[quote="EarlgreyTea"]ログをざっと見て気づいたことを書いておきます。 - 127.0.0.1:8823 のスコープで webappsstore2 にアクセスしてるのは grayスキンが履歴更新しているのみです。
- アプリタブで twitterとYouTubeを開いているのですが、https://twitter.com と https://www.youtube.com が高頻度でwebappsstore2にアクセスし続けている。
twitterが時々ユーザープロファイルのでかいデータを更新している
grayスキンの中だけで頻繁に競合が発生するとは思えないから、 複数の、異なるkeyのsetItem()で、行の範囲の更新ロックの競合が起こる ⇒ grayスキンが勝ち、他にはSQLITE_BUSY ⇒ grayスキンが、行の書き込みロックをとる ⇒ SQLITE_BUSYが返ったほうで、grayスキンの処理が完了する前に、ROLLBACK ⇒ ROLLBACKが勝って、他のリクエストのROLLBACKが処理される ⇒ grayスキンにSQLITE_ABORTが返る。おそらく、行の範囲の更新ロックはフリーされる。 ⇒ SQLITE_ABORTで何もしなくて、ROLLBACKを出さないから、行の書き込みロックは保持されたまま ⇒ grayスキンで同じ行の更新が入ると、SQLITE_BUSY ⇒ ROLLBACK ⇒ SQLITE_BUSY ⇒ あの、Rollback()によるROLLBACKの場合は、無限ループ ⇒ Read(getItem)はできるから、更新したはずの行が更新されていない、という現象が起こる という感じかな?
[quote="EarlgreyTea"]ログをざっと見て気づいたことを書いておきます。 [list] [*]127.0.0.1:8823 のスコープで webappsstore2 にアクセスしてるのは grayスキンが履歴更新しているのみです。 [*]アプリタブで twitterとYouTubeを開いているのですが、https://twitter.com と https://www.youtube.com が高頻度でwebappsstore2にアクセスし続けている。 twitterが時々ユーザープロファイルのでかいデータを更新している[/list]
grayスキンの中だけで頻繁に競合が発生するとは思えないから、 複数の、異なるkeyのsetItem()で、行の範囲の更新ロックの競合が起こる ⇒ grayスキンが勝ち、他にはSQLITE_BUSY ⇒ grayスキンが、行の書き込みロックをとる ⇒ SQLITE_BUSYが返ったほうで、grayスキンの処理が完了する前に、ROLLBACK ⇒ ROLLBACKが勝って、他のリクエストのROLLBACKが処理される ⇒ grayスキンにSQLITE_ABORTが返る。おそらく、行の範囲の更新ロックはフリーされる。 ⇒ SQLITE_ABORTで何もしなくて、ROLLBACKを出さないから、行の書き込みロックは保持されたまま ⇒ grayスキンで同じ行の更新が入ると、SQLITE_BUSY ⇒ ROLLBACK ⇒ SQLITE_BUSY ⇒ あの、Rollback()によるROLLBACKの場合は、無限ループ ⇒ Read(getItem)はできるから、更新したはずの行が更新されていない、という現象が起こる という感じかな?
|
|
|
|
Posted: 2015年3月08日(日) 15:00 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
WADA さんが書きました: key='skin.gray2x',でInsertかReplace(localStorageだから、setItem)ですが、これは、件のスキンのものですか? はいそうです。chaikaは 127.0.0.1:8823 のローカルプロキシで動作しますのでgrayスキンもそのスコープでストレージに保存します。 WADA さんが書きました: Bug 1062823 と Bug 951934 に、このログの件を報告しておきました。 http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638Statement::ExecuteStep error: のログは、 638 int srv = mDBConnection->stepStatement(mNativeConnection, mDBStatement); でエラーが返った時に書かれます。 おおう、行動が速いですね。エラーの箇所についてはこちらも初めてソースをダウンロードして検索して確認しました。 ログをざっと見て気づいたことを書いておきます。 - 127.0.0.1:8823 のスコープで webappsstore2 にアクセスしてるのは grayスキンが履歴更新しているのみです。
- アプリタブで twitterとYouTubeを開いているのですが、https://twitter.com と https://www.youtube.com が高頻度でwebappsstore2にアクセスし続けている。twitterが時々ユーザープロファイルのでかいデータを更新しているのにちょっとびっくりしました。
なにか参考になれば幸いです。
[quote="WADA"]key='skin.gray2x',でInsertかReplace(localStorageだから、setItem)ですが、これは、件のスキンのものですか?[/quote] はいそうです。chaikaは 127.0.0.1:8823 のローカルプロキシで動作しますのでgrayスキンもそのスコープでストレージに保存します。
[quote="WADA"] [url=https://bugzilla.mozilla.org/show_bug.cgi?id=1062823]Bug 1062823[/url] と [url=https://bugzilla.mozilla.org/show_bug.cgi?id=951934]Bug 951934[/url] に、このログの件を報告しておきました。
[url=http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638]http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638[/url] Statement::ExecuteStep error: のログは、 638 int srv = mDBConnection->stepStatement(mNativeConnection, mDBStatement); でエラーが返った時に書かれます。 [/quote] おおう、行動が速いですね。エラーの箇所についてはこちらも初めてソースをダウンロードして検索して確認しました。 ログをざっと見て気づいたことを書いておきます。 [list] [*]127.0.0.1:8823 のスコープで webappsstore2 にアクセスしてるのは grayスキンが履歴更新しているのみです。[/list][list] [*]アプリタブで twitterとYouTubeを開いているのですが、https://twitter.com と https://www.youtube.com が高頻度でwebappsstore2にアクセスし続けている。twitterが時々ユーザープロファイルのでかいデータを更新しているのにちょっとびっくりしました。[/list]なにか参考になれば幸いです。
|
|
|
|
Posted: 2015年3月08日(日) 02:11 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
EarlgreyTea さんが書きました: 結局、エラーには関係ありませんでした。履歴の消去とかの操作をしないと実行しない箇所だったので。 既にロックアウトが発生していて、たまたま履歴の消去とかの操作をしたのであのコードを通り、SQLITE_BUSYが引っかかった、という感じですね。 mozStorage:5 というのがありましたか。 コード: 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK'
'1.0.0.721.:http:8823' は、おそらくscopeそのままで、URLとしては、http://127.0.0.1:8823、 loopback? for 'ROLLBACK' ときて、database is locked、とくると、ROLLBACKにSQLITE_BUSY、が怪しいですね。 key='skin.gray2x',でInsertかReplace(localStorageだから、setItem)ですが、これは、件のスキンのものですか? そうならば、JvaScriptのsetItemなどのコールのところのcatch(e)で引っ掛けらる? mozStorage:5 のログとあわせれば、2013/9から放置しているバグによって問題が実際に起こった、という証拠を叩き突きつけられる(^^) [追記] Bug 1062823 と Bug 951934 に、このログの件を報告しておきました。 http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638Statement::ExecuteStep error: のログは、 638 int srv = mDBConnection->stepStatement(mNativeConnection, mDBStatement); でエラーが返った時に書かれます。 [/追記おわり]
[quote="EarlgreyTea"]結局、エラーには関係ありませんでした。履歴の消去とかの操作をしないと実行しない箇所だったので。[/quote] 既にロックアウトが発生していて、たまたま履歴の消去とかの操作をしたのであのコードを通り、SQLITE_BUSYが引っかかった、という感じですね。
mozStorage:5 というのがありましたか。 [code] 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK' [/code] '1.0.0.721.:http:8823' は、おそらくscopeそのままで、URLとしては、http://127.0.0.1:8823、 loopback? for 'ROLLBACK' ときて、database is locked、とくると、ROLLBACKにSQLITE_BUSY、が怪しいですね。
key='skin.gray2x',でInsertかReplace(localStorageだから、setItem)ですが、これは、件のスキンのものですか? そうならば、JvaScriptのsetItemなどのコールのところのcatch(e)で引っ掛けらる? mozStorage:5 のログとあわせれば、2013/9から放置しているバグによって問題が実際に起こった、という証拠を叩き突きつけられる(^^)
[追記] [url=https://bugzilla.mozilla.org/show_bug.cgi?id=1062823]Bug 1062823[/url] と [url=https://bugzilla.mozilla.org/show_bug.cgi?id=951934]Bug 951934[/url] に、このログの件を報告しておきました。
[url=http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638]http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageStatement.cpp#638[/url] Statement::ExecuteStep error: のログは、 638 int srv = mDBConnection->stepStatement(mNativeConnection, mDBStatement); でエラーが返った時に書かれます。 [/追記おわり]
|
|
|
|
Posted: 2015年3月07日(土) 17:58 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
引用: とりあえず removeItem(key) に修正してしばらく様子を見てみます。 のその後の報告です。結局、エラーには関係ありませんでした。履歴の消去とかの操作をしないと実行しない箇所だったので。 それで別トピックに触発されて timestamp,mozStorage:5 のNSPRログを出してしばらく運用していたのですが、1回だけエラー発生時のログを取ることができました。 発生時点のログは以下のようなものです(データ内容は削っています)。 コード: 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'BEGIN DEFERRED' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK'
ちなみに、削った value はスレッドの閲覧のたびに更新される履歴情報(多めに100件)や設定値などが格納されていてサイズが16KB近くあります。
[quote]とりあえず removeItem(key) に修正してしばらく様子を見てみます。[/quote]のその後の報告です。結局、エラーには関係ありませんでした。履歴の消去とかの操作をしないと実行しない箇所だったので。 それで別トピックに触発されて timestamp,mozStorage:5 のNSPRログを出してしばらく運用していたのですが、1回だけエラー発生時のログを取ることができました。 発生時点のログは以下のようなものです(データ内容は削っています)。 [code] 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'BEGIN DEFERRED' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'INSERT OR REPLACE INTO webappsstore2 (scope, key, value) VALUES ('1.0.0.721.:http:8823', 'skin.gray2x', '{ ... }') ' 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: Statement::ExecuteStep error: database is locked 2015-03-06 05:44:35.927000 UTC - 3480[1b7fbef0]: sqlite3_trace on 22ea6d60 for 'ROLLBACK' [/code] ちなみに、削った value はスレッドの閲覧のたびに更新される履歴情報(多めに100件)や設定値などが格納されていてサイズが16KB近くあります。
|
|
|
|
Posted: 2015年3月07日(土) 17:05 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
EarlgreyTea さんが書きました: あらためてコード見なおしたら clear(key) となっていたので書き間違いな気がします。 デバッガーのスクリーンショットを見ると、flash(flushではない)の中のclear()が、self.storage.clear(self.key) となっていますね。 気がつかなかった(^^; self==thisで、self.keyは、self.itemが空では無い時に行っている、self.storage.setItem(self.key,JSON.stringify(self.item)) で使うキーです。 import(storageKey,itemKeys) の中では、var item=JSON.parse(this.storage.getItem(storageKey)を行い、 itemKeysで指定されたkeyについて、JSON.parseで得たitemの中のデータを、this.item[key]に入れています。 多分、このコードのlocalStorageは自前のオブジェクトで、this.storageに本物のlocalStorage(window.localStorage)、this.keyにJSONデータのキー、.this.itemに実行中に使う各種設定データを入れているのでしょう。 this.flash()は、次回のためにthis.itemの内容を、JSONデータとして、window.localStorageにthis.keyをキーとして保存するコード、に見えます。 だとすると、this.flash()で、self.itemが空の時に行っているself.storage.clear(self.key)は、 保存するデータが無いので、window.localStorageのthis.keyをキーとするJSONデータを消す、ということなのでしょう。 そうであるならば、ここでのclear()の使用は、多分removeItem()との混同でしょう。 self.itemが空の状態で呼ばれたら全部の行を消し、self.itemが空の状態ではないならばJSONデータを保存、というコードの仕様も有りですけど、それならば、self.storage.clear(self.key)であってはならない。 self.item(this.item)が空の時はself.storage.setItem(self.key,JSON.stringify( {} )でよくて、こっちを使っていれば、clear()の誤用も起こり得ないし、バグにも遭遇しないはず... 他でもclear(key)が見られるのならば、clear()の多用ではなく、clear()の誤用になります。 もし、clear()の誤用があり、上記のself.itemのJSONデータ以外についてもsetItem()/removeItem()を行っていて、その頻度が高ければ、 clear()とsetItem()/removeItem()の間の競合、clear()とclear()の間の競合、が起こり得て、 おっつけ、clear()でROLLBACKを出した時にSQLITE_ABORT_ROLLBACKが返ることも発生するでしょう。 そうなれば、ROLLBACKを再発行しない問題が起こり、その時には結構高い確率でリリースされないロックが発生すると思います。
[quote="EarlgreyTea"]あらためてコード見なおしたら clear(key) となっていたので書き間違いな気がします。[/quote] デバッガーのスクリーンショットを見ると、flash(flushではない)の中のclear()が、self.storage.clear(self.key) となっていますね。 気がつかなかった(^^;
self==thisで、self.keyは、self.itemが空では無い時に行っている、self.storage.setItem(self.key,JSON.stringify(self.item)) で使うキーです。 import(storageKey,itemKeys) の中では、var item=JSON.parse(this.storage.getItem(storageKey)を行い、 itemKeysで指定されたkeyについて、JSON.parseで得たitemの中のデータを、this.item[key]に入れています。 多分、このコードのlocalStorageは自前のオブジェクトで、this.storageに本物のlocalStorage(window.localStorage)、this.keyにJSONデータのキー、.this.itemに実行中に使う各種設定データを入れているのでしょう。 this.flash()は、次回のためにthis.itemの内容を、JSONデータとして、window.localStorageにthis.keyをキーとして保存するコード、に見えます。 だとすると、this.flash()で、self.itemが空の時に行っているself.storage.clear(self.key)は、 保存するデータが無いので、window.localStorageのthis.keyをキーとするJSONデータを消す、ということなのでしょう。
そうであるならば、ここでのclear()の使用は、多分removeItem()との混同でしょう。 self.itemが空の状態で呼ばれたら全部の行を消し、self.itemが空の状態ではないならばJSONデータを保存、というコードの仕様も有りですけど、それならば、self.storage.clear(self.key)であってはならない。 self.item(this.item)が空の時はself.storage.setItem(self.key,JSON.stringify( {} )でよくて、こっちを使っていれば、clear()の誤用も起こり得ないし、バグにも遭遇しないはず...
他でもclear(key)が見られるのならば、clear()の多用ではなく、clear()の誤用になります。 もし、clear()の誤用があり、上記のself.itemのJSONデータ以外についてもsetItem()/removeItem()を行っていて、その頻度が高ければ、 clear()とsetItem()/removeItem()の間の競合、clear()とclear()の間の競合、が起こり得て、 おっつけ、clear()でROLLBACKを出した時にSQLITE_ABORT_ROLLBACKが返ることも発生するでしょう。 そうなれば、ROLLBACKを再発行しない問題が起こり、その時には結構高い確率でリリースされないロックが発生すると思います。
|
|
|
|
Posted: 2015年2月24日(火) 14:57 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
あらためてコード見なおしたら clear(key) となっていたので書き間違いな気がします。とりあえず removeItem(key) に修正してしばらく様子を見てみます。
あらためてコード見なおしたら clear(key) となっていたので書き間違いな気がします。とりあえず removeItem(key) に修正してしばらく様子を見てみます。
|
|
|
|
Posted: 2015年2月23日(月) 22:21 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
EarlgreyTea さんが書きました: try/catch は元からなんです。なんで入っていたのかは作者さんに聞かないとわかりませんが、 「データの保存に失敗しました。しおりや履歴を消去して再度試してください」というちゃんとしたメッセージを出していたところからすると、たびたび発生していたのかもしれません。 何故かエントリーが消えていないことに気づき、clear()をtry/catchにいれてみた。 ⇒ scope内のどの行で永久SQLITE_BUSYが起こっても、clear()だとエラーを検出するので、alert()が時々出る ⇒ それで、ちゃんとしたメッセージにした、 という気が... そして、clear()で頻繁にエラーを検出、ということは、clear()を多用していることの裏返しのはず。 ROLLBACKに対してSQLITE_ABORT_ROLLBACKが返って来た時に、 ちゃんとROLLBACKを再度ださないとロックが残ってしまうことが起こり得るのは、 一回のリクエストで複数の行に対して更新を行う、clear()だけ。 他のリクエストの場合は、一行だけに対するリクエストだから、 SQLITE_BUSYが返って来た時にはその行のロックをとれなかったことは保証されている。 従って、その後、たとえ、ROLLBACKでSQLITE_ABORT_ROLLBACKが返り、 その時にROLLBACKを再度ださない、ということが発生しても、ロックが残ってしまうことは起こり得ない。 そうなると、件のアプリケーションが頻繁にclear()を出すことが、件のアプリケーションで頻繁に永久SQLITE_BUSYを見られる理由である、と言えます。 clear()は、あるscope()==Webサイトのもの全部のremoveItemだから、普通は頻繁にだすことは考えにくい。 http://www.google.com.の直下の、foo-1.html, foo-2.html, ... , .foo-N.html,、の全員が、 同じscope=http://www.google.comを使うのだから、 通常のHTML内のスクリプトが、localStorage.clear()を頻繁にだすとは思えない。 普通は、手動で、Firefocのメニューから履歴のクリアーを行った時くらい。 そう考えると、clear()を頻繁にだすのでバグに遭遇してしまう、ということになります。 [追記] となると、現時点の回避策は、そのアプリの全てのlocalStorage.clear()を以下のように変えること、になってきます。 // keyの順番の後ろから try{ while(0<localStorage.length) loalStrage.removeItem( localStrage.key( localStorage.length-1 ) ) ; } catch(e) { var err=e; var ll_err=localStorage.length; var key_err = localStrage.key(localStorage.length-1) ; // keyの順番の前から try{ while(0<localStorage.length) loalStrage.removeItem( localStrage.key(0) ) ; } catch(e) {var err2=e: var ll_err2=localStorage.length; var key_err2 = localStrage.key(0) ; } alert( ll_err + ket_err + ll_err2 + key_err2 ) ; alert( err ); if(err2) alert( err2 ); } clear()は使わないでremoveItem()を使う、というだけ。 途中で行が他のリクエストと競合してSQLITE_BUSYが返っても、 それは、その行のremoveItem()の中で処理してリトライしてくれるから、 ロックを残してしまう「クリアー」が発生しない。 そして、何か異常があってremoveItem()でエラーがあっても、clear()の時と同様に、上記のコードで捉えられる。 [/追記]
[quote="EarlgreyTea"]try/catch は元からなんです。なんで入っていたのかは作者さんに聞かないとわかりませんが、 「データの保存に失敗しました。しおりや履歴を消去して再度試してください」というちゃんとしたメッセージを出していたところからすると、たびたび発生していたのかもしれません。[/quote] 何故かエントリーが消えていないことに気づき、clear()をtry/catchにいれてみた。 ⇒ scope内のどの行で永久SQLITE_BUSYが起こっても、clear()だとエラーを検出するので、alert()が時々出る ⇒ それで、ちゃんとしたメッセージにした、 という気が... そして、clear()で頻繁にエラーを検出、ということは、clear()を多用していることの裏返しのはず。
ROLLBACKに対してSQLITE_ABORT_ROLLBACKが返って来た時に、 ちゃんとROLLBACKを再度ださないとロックが残ってしまうことが起こり得るのは、 一回のリクエストで複数の行に対して更新を行う、clear()だけ。 他のリクエストの場合は、一行だけに対するリクエストだから、 SQLITE_BUSYが返って来た時にはその行のロックをとれなかったことは保証されている。 従って、その後、たとえ、ROLLBACKでSQLITE_ABORT_ROLLBACKが返り、 その時にROLLBACKを再度ださない、ということが発生しても、ロックが残ってしまうことは起こり得ない。
そうなると、件のアプリケーションが頻繁にclear()を出すことが、件のアプリケーションで頻繁に永久SQLITE_BUSYを見られる理由である、と言えます。 clear()は、あるscope()==Webサイトのもの全部のremoveItemだから、普通は頻繁にだすことは考えにくい。 http://www.google.com.の直下の、foo-1.html, foo-2.html, ... , .foo-N.html,、の全員が、 同じscope=http://www.google.comを使うのだから、 通常のHTML内のスクリプトが、localStorage.clear()を頻繁にだすとは思えない。 普通は、手動で、Firefocのメニューから履歴のクリアーを行った時くらい。 そう考えると、clear()を頻繁にだすのでバグに遭遇してしまう、ということになります。
[追記] となると、現時点の回避策は、そのアプリの全てのlocalStorage.clear()を以下のように変えること、になってきます。 // keyの順番の後ろから try{ while(0<localStorage.length) loalStrage.removeItem( localStrage.key( localStorage.length-1 ) ) ; } catch(e) { var err=e; var ll_err=localStorage.length; var key_err = localStrage.key(localStorage.length-1) ; // keyの順番の前から try{ while(0<localStorage.length) loalStrage.removeItem( localStrage.key(0) ) ; } catch(e) {var err2=e: var ll_err2=localStorage.length; var key_err2 = localStrage.key(0) ; } alert( ll_err + ket_err + ll_err2 + key_err2 ) ; alert( err ); if(err2) alert( err2 ); }
clear()は使わないでremoveItem()を使う、というだけ。 途中で行が他のリクエストと競合してSQLITE_BUSYが返っても、 それは、その行のremoveItem()の中で処理してリトライしてくれるから、 ロックを残してしまう「クリアー」が発生しない。 そして、何か異常があってremoveItem()でエラーがあっても、clear()の時と同様に、上記のコードで捉えられる。 [/追記]
|
|
|
|
Posted: 2015年2月20日(金) 18:15 |
|
|
|
|
|
記事の件名: |
Re: 長時間使用してるとLocalStorage保存でエラー発生する |
|
|
あ、変な書き方しちゃってごめんなさい。try/catch は元からなんです。なんで入っていたのかは作者さんに聞かないとわかりませんが、「データの保存に失敗しました。しおりや履歴を消去して再度試してください」というちゃんとしたメッセージを出していたところからすると、たびたび発生していたのかもしれません。ただ同じ状況だとすると「しおりや履歴の消去」自体ができないはずなので、昔のバージョンではサイズの制限?のエラーが出てた?のかな。
あ、変な書き方しちゃってごめんなさい。try/catch は元からなんです。なんで入っていたのかは作者さんに聞かないとわかりませんが、「データの保存に失敗しました。しおりや履歴を消去して再度試してください」というちゃんとしたメッセージを出していたところからすると、たびたび発生していたのかもしれません。ただ同じ状況だとすると「しおりや履歴の消去」自体ができないはずなので、昔のバージョンではサイズの制限?のエラーが出てた?のかな。
|
|
|
|
Posted: 2015年2月18日(水) 00:59 |
|
|
|
|