(致命的な不具合) 2MB前後以上のアクティビティログのノートにMac版Evernoteで文字入力で8分以上の異常遅延

[KakiShibu 1]

(1)Evernote

　Evernote Mac 2.0 Beta 2 (115692)〜2.0 (116546)

(2)環境

　MacOSX 10.6.5

　Macmini Core 2 Duo 2GHz, 2GB 667 MHz DDR2 SDRAM

(3) 不具合現象の概要と要望

「(致命的な不具合) 文字入力・日本語入力・かな入力の数々の不具合は我慢の限界に達しています」

では、日本語入力での5秒以上の遅延でしたが(Mac版ver2.0 Beta 2､正式ver2.0でも未解決) 、

それをはるかに超える8分以上もの異常遅延(固定現象)に遭遇しました。

しかも、今回のケースでは、英字モードの入力でさえ発生します。

Win版Evernote4.1.0では、このような遅延は起きない。

日本語入力遅延も含めて､

Mac版Evernoteには文字入力による異常な遅延という爆弾(バグ)が複数あるのは明らかです。

Webクリップの場合､HTML構造は一定しませんが、

アクティビティログは､Evernote自身が作成している単純な構造のデータなので、そこでこのような異常遅延が起きるのは問題外ですが、このバグを直す上では都合がいいかもしれません。

これは､単に「アクティビティログ」だけの問題ではなく､Webクリップも含めた根本的な問題です。

5秒でも許せない遅延ですが､8分以上の遅延は、もはや、使用に耐えない。

これを放置しておくのは、Evernote社にとっても我々ユーザーにとっても多大な不利益につながるので、

日本語入力の遅延も含めて､大至急､この不具合を解決してください。

これは､米国サイドが直すのを待っているしかない､というようなレベルではないので､

ホットラインを通じて米国サイドに改善を緊急要請してください。

sugai様など日本人スタッフご自身で先ずはMacで現象を確認していただけませんか?

Win版で問題ないことも含めて。

よろしくお願いします。

(4) 現象の詳細

「(要望)膨大なノートデータが既にある場合の再インストール等におけるローカルデータの再ダウンロードの問題点と要望 」で説明したWin版のバージョンアップ時に気づいた現象です。

「Evernote for Windows 4.1.0.3365 (115466) Public」のインストールが何度やっともうまく行かず､

結局､Cディスク容量不足だろうとやっと気づき､ローカルファイルの保存先をEディスクに変えて､

インストールとローカルファイル(約3000個のノート・サイズ約2.5GB)の再ダウンロードが4時間かかって完了しました。

その時のアクティビティログ(なんとサイズが4.1MB)を「Copy to Clipboard」でコピーして､新規ノートにペーストしました。

アクティビティログを採取したのは今回が初めてです。

比較テスト用に以下のような5つのノートを作成しました。

　　ノートW#1(4.1MB):

　　　　Win版4.1.0でアクティビティログを全選択し「Copy to Clipboard」､新規ノートにペースト。

　　ノートW#1-1(955KB):

　　　　Win版4.1.0でアクティビティログの最初の約4分の1を「Copy to Clipboard」､新規ノートにペースト。

　　　　これは正常。

　　ノートW#1-2(2.3MB):

　　　　Win版4.1.0でアクティビティログの最初の約4分の2を「Copy to Clipboard」､新規ノートにペースト。

　　ノートW#1-3(3.2MB):

　　　　Win版4.1.0でアクティビティログの最初の約4分の3を「Copy to Clipboard」､新規ノートにペースト。

　　ノートM#1(2.2MB):

　　　　Mac版2.0Beta2でアクティビティログを全選択し「クリップボードにコピー」､新規ノートにペースト。

(4-1) 最初の気づき

　ノートW#1をMac版ver2.0 Beta 2で開いて､ノート内部に文字を入力したところ､レインボー風車が回り出し､

　何分経っても入力した文字も現れないので､Evernoteを強制終了しました。

　日本語入力遅延の極端な例なのかどうかを確かめるため､英字モードで「e」を打ち込んでみても､

　やはり同様の現象で､強制終了しました。

(4-2)結論

いろいろ試してみた結果､

　・アクティビティログのサイズが955KBでは問題なく､

　　サイズ955KB〜2.3MBの間のどこかに異常遅延するかしないかの境界がある。

　・Win版Evernote(ver4)は正常で､Mac版(ver2)は明らかに異常遅延が起きる。

　・Webクリップに日本語を入力したときの遅延(5秒〜10秒以上)に比べても､明らかに遅延が長い(8分以上)。

　・遅延時間はノートサイズ(ログサイズ)の2乗より若干長めに比例して加速度的に増大して行く。

　　　■ノートW#1-1(955KB)　: 遅延時間 なし

　　　■ノートW#1-2(2.3MB)　: 遅延時間 8〜9分16秒

　　　■ノートW#1-3(3.2MB)　: 遅延時間 18分30秒

　　　■ノートW#1(4.1MB)　　: 遅延時間 32分

　・Webクリップで遅延が起きるのは日本語入力だけですが､

　　アクティビティログでの遅延は英字モードでも起きるので、

　　今回のバグは､日本語入力システムとは無関係です。

　　プルダウンメニューの「ペースト」やCommand+Vでも全く同様の遅延が起きるからです。

　・レインボー風車が回り遅延している間に､

　　　　・EvernoteのCPU使用率が6%前後から一気に90%以上に跳ね上がる。

　　　　・アクティビティログにはこの間何も追加表示がない。

　　　　・Evernoteは「無応答」という表示になる(強制終了パネルなどで)。

　・これだけ処理が中断した後のためだと思うが､入力した文字が現れるとすぐに同期が始まる。

　・Mac版Evernoteで採取したアクティビティログ(2.2MB: ノートM#1)と

　　Win版Evernoteで採取したアクティビティログ(2.3MB: ノートW#1-2)を比較すると､

　　サイズはほぼ同じなのに､

　　後者の方が遅延時間が圧倒的に長い(前者: 遅延2分30秒・同期1分20秒程度、後者: 遅延8分・同期1分程度)。

　　Win版とMac版の文字コードの違いなのか?

　・遅延の起きるときに2文字打ち込んでも(たとえで「ff」)、遅延後に表示されるのは1文字のみ。

　　つまり､1文字打ち込んだ瞬間に遅延が起きて2文字目の入力は廃棄されるということ。

　・Mac版のアクティビティログで、

　　　　・「DEBUG」という表記のメッセージがあるのが怪しい。

　　　　　　Beta版はともかくとして、正規版でこのようなメッセージがあること、

　　　　　　つまりは、何らかの余計な処理をしていることはまずい。

　　　　・「DEBUG」メッセージの中の [ENQuotaUsageLevelIndicator] 、[ENNoteThumbnailManager]

　　　　　　というカテゴリーが怪しい。

　　　　・特に､ノートのサムネールを作成するというのが一番怪しい。

　　　　　どんなサムネールかは分からないが､ノート用と書いてあるので､

　　　　　このサムネールを作成することが異常な遅延を生んでいる可能性が高い。

　　　　　ログサイズのほぼ2乗に比例して遅延時間が増大することから考えても､ここに原因がありそうです。

(4-3) 比較テスト

遅延の起きるときと起きないときのアクティビティログの出方を確かめる。

(テスト3-1) 遅延の起きないケース、ノートW#1-1(955KB)で文字を一文字入力し､直後に同期ボタンを押したときのログをMacとWinで比較

　ログの表示形式が全く違うので非常に見にくい。

　もう少し統一した方がいい。

　(テスト3-1-1) Version: Evernote Mac 2.0 Beta 2 (115692)および、Version: Evernote Mac 2.0 (116546)で:

2010-12-17 00:29:40 0xa125a0 [ENQuotaUsageLevelIndicator] DEBUG: -[ENQuotaUsageLevelIndicator generateCachedImages]: 0x16952c60

2010-12-17 00:29:40 0x196dba10 [ENSyncEngine] INFO: Contacting Evernote server...

2010-12-17 00:29:40 0xac4eb0 [ENNoteThumbnailManager] DEBUG: Generating thumbnail for note: 'ノートW#1-1(955KB)'

2010-12-17 00:29:40 0xac4eb0 [ENNoteThumbnailManager] DEBUG: guid: 47311487-5532-4d9f-826f-dd05308b61c5

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: current update count: 116740

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Updating local user info from server

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Upload used from server: 241780003

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Nothing to pull down from server.

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Uploading changes...

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Sending tag changes...

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Sending search changes...

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Sending notebook changes...

2010-12-17 00:29:41 0x196dba10 [ENSyncEngine] INFO: Sending note changes...

2010-12-17 00:29:42 0x196dba10 [ENSyncEngine] INFO: Syncing note 'ノートW#1-1(955KB)' [47311487-5532-4d9f-826f-dd05308b61c5]

2010-12-17 00:30:10 0xa125a0 [ENQuotaUsageLevelIndicator] DEBUG: -[ENQuotaUsageLevelIndicator generateCachedImages]: 0x16952c60

2010-12-17 00:30:10 0x196dba10 [ENSyncEngine] DEBUG: skipped 51 never-synced trashed notes

　　　　　　　　　　　　　　　　　　　　　　　　　←これはゴミ箱(61個のノート)の中のデータだろう。

2010-12-17 00:30:10 0x196dba10 [ENSyncEngine] INFO: Sending linked notebook changes...

2010-12-17 00:30:10 0x196dba10 [ENSyncEngine] INFO: Syncing content of linked notebooks...

2010-12-17 00:30:10 0x196dba10 [ENSyncEngine] INFO: Sync complete.

　(テスト3-1-2) Evernote for Windows 4.1.0.3365 (115466) Publicで:

00:40:04 [2184] 0% Connecting to http://www.evernote.com

00:40:04 [2184] 0% * loaded updateCount: 116742

00:40:04 [2184] 0% Client is up to date with the server, updateCount=116742

00:40:04 [2184] 0% * saved updateCount: 116742

00:40:05 [2184] 0% Updating server items

00:40:05 [2184] 0% Updating server note "ノートW#1-1(955KB)"

00:40:05 [2184] 0% * guid={47311487-5532-4d9f-826f-dd05308b61c5}

00:42:12 [2184] 0% * updateCount: 116742 --> 116743

00:42:12 [2184] 100% * saved updateCount: 116743

00:42:13 [2184] 100% Session terminated normally, elapsed time: 2m 9s

00:42:13 [2184] 100% * sent: 974KB, received: 494B

00:42:13 [2184] 100% * 2m 8s (99%) spent in EDAM RPC

00:42:13 [2184] 0% Connecting to http://www.evernote.com

00:42:13 [2184] 0% * loaded updateCount: 116743

00:42:14 [2184] 0% Client is up to date with the server, updateCount=116743

00:42:14 [2184] 0% * saved updateCount: 116743

00:42:15 [2184] 0% Session terminated normally, elapsed time: 1s

00:42:15 [2184] 0% * sent: 228B, received: 138B

00:42:15 [2184] 0% * 1s (70%) spent in EDAM RPC

　(テスト3-2) ノートW#1-2(2.3MB)で英字モードにして

　　　　　　「ggg」をキー入力し9分以上の遅延が起きたときのアクティビティログの出方

　　キーを打ち込んでから遅延が起きている間は､アクティビティログには何も表示されない。

　　打ち込んだ文字も表示されない。

　　そして、9分16秒後に､打ち込んだ3文字ではなく1文字「g」だけが現れ､文字カレットが点滅を始め、

　　以下の4行だけが表示された。

2010-12-17 14:42:47 0xa12570 [ENQuotaUsageLevelIndicator] DEBUG: -[ENQuotaUsageLevelIndicator generateCachedImages]: 0xac5740

2010-12-17 14:42:48 0xdd7e60 [ENNoteThumbnailManager] DEBUG: Generating thumbnail for note: 'ノートW#1-2(2.3MB)'

2010-12-17 14:42:48 0xdd7e60 [ENNoteThumbnailManager] DEBUG: guid: 96c93517-e369-4730-addd-cff46d264b41

2010-12-17 14:42:49 0x268d9520 [ENSyncEngine] INFO: Contacting Evernote server...

　　　　　　←pm2:42:47 先ずは「g」が表示されたときにここまで表示した。

　　　　　　　この4行の表記は、(テスト3-1-1) で同期ボタンを押したときにも最初に出るメッセージですが､

　　　　　　　最初の3行、特に､ノートのサムネールを作成、というDEBUGメッセージは、

　 　　　　　 同期ボタンを押す前にすでに実行していたと考えれば､辻褄が合う。

　　　　　　　遅延の起きない場合でも､キー入力してからバックグラウンドでこのサムネール作成が実行され

　　　　　　　ていると思われる。

　　　　　　　メッセージが出るのは､同期ボタンを押したことを契機としているだけでしょう。

　　　　　　　そして、遅延が起きたときは､バックグラウンド実行に渡すところで戻ってこれなくなっている

　　　　　　　のだろうと考えられます。

　　　　　　　結局､遅延の無いようなサイズの小さいログの場合でも､実際には､わずかな遅延が起きている

　　　　　　　可能性もあるかもしれない。

　　　　　　　遅延がノートサイズのほぼ2乗に比例して増大することから考えても､

　　　　　　　ノートのサムネールの作成がノートサイズが大きくなればなるほど時間がかかると考える

　　　　　　　と辻褄が合う。

2010-12-17 14:42:49 0x268d9520 [ENSyncEngine] INFO: current update count: 117056

2010-12-17 14:42:49 0x268d9520 [ENSyncEngine] INFO: Updating local user info from server

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Upload used from server: 242181957

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Nothing to pull down from server.

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Uploading changes...

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Sending tag changes...

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Sending search changes...

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Sending notebook changes...

2010-12-17 14:42:50 0x268d9520 [ENSyncEngine] INFO: Sending note changes...

　　　　　　←pm2:42:50 同期が自動的に始まって次にここまで表示された。

2010-12-17 14:42:55 0x268d9520 [ENSyncEngine] INFO: Syncing note 'ノートW#1-2(2.3MB)' [96c93517-e369-4730-addd-cff46d264b41]

　　　　　　←pm2:42:57 ここまで表示された。

2010-12-17 14:43:45 0xa12570 [ENQuotaUsageLevelIndicator] DEBUG: -[ENQuotaUsageLevelIndicator generateCachedImages]: 0xac5740

2010-12-17 14:43:45 0x268d9520 [ENSyncEngine] DEBUG: skipped 52 never-synced trashed notes

2010-12-17 14:43:45 0x268d9520 [ENSyncEngine] INFO: Sending linked notebook changes...

2010-12-17 14:43:45 0x268d9520 [ENSyncEngine] INFO: Syncing content of linked notebooks...

2010-12-17 14:43:45 0x268d9520 [ENSyncEngine] INFO: Sync complete.

　　　　　　←pm2:43:44 ここまで表示され同期完了。

(5)その他

Macでは、プルダウンメニューでは､「ヘルプ----アクティビティログ...」ですが、

実際のウィンドウ上部に「活動記録」というべたな直訳になっていておかしい。

「クリップボードにコピー」ボタンも実際の動作が分かりにくいので、ちょっと長くなってしまいますが

　　　『ヘッダー付きでクリップボードにコピー』、あるいは、短くして､

　　　『ヘッダー付きコピー』

とした方が分かりやすい。右クリックメニューの「コピー」と区別するためです。

[sugai 0]

タイトルに「アクティビティログ」と入っていますが、つまりは容量の大きいテキストをノートで取り扱っているとき、入力や選択をしようとすると遅延が起こりますね。2.1MBのテキストファイルをノートにコピペして作業しようとすると、テキストが数秒遅れて入力されたり、全選択しようとするとレインボーカーソルが回ったりということが確かに発生します。

Core 2 Duo のMacBookでやってみましたが、レンボーカーソルが回っている間、CPUが片肺状態になっていました。

優先順位を上げてEvernote社に報告します（と書くと他人事のように聞こえるかもしれませんが、私自身外部の人間でして、フォーラムにおいてコミュニケーションのパイプ役を承っている状況なので、すみません。報告自体は定期的に上げてまして、対応の催促も日々強くかけております）。

[KakiShibu 1]

やはり、sugai様のMacでも遅延は起きているんですね｡

『2.1MBのテキストファイルでテキストが数秒遅れて入力、全選択しようとするとレインボーカーソルが発生』

というのは、軽めの症状ですね｡

それに比べると､アクティビティログの遅延は、今まで私が経験した中では断トツです。

確かに､普通の「応答なし」は本当に1時間経っても応答なしのままという場合がほとんどなので、

区別がつかないのですが､

今回のアクティビティログの「応答なし」はCPU使用率が90%越えとなって、無限ループに近い状態にありますが､

確実に有限の時間(8分以上)で復帰します｡そこが､普通の「応答なし」との違いです｡

ですが、現実的には､8分も待つほど気が長い人はいないので、

強制終了してしまうので､この違いに気づいている人がいないのも仕方ないでしょう｡

なぜアクティビティログの場合がこれほど異常な遅延が起きるのかを考えてみると､

アクティビティログのデータ構造が、

　　　

の繰り返し

という単純な構造であることが原因と考えられます｡

つまり、

タグを解釈するルーチンが2万個以上の

タグを解釈するときに、

そのルーチンが多重に呼び出されることで､

無限ループのような､待機状態の連続となって、それで、8分以上の遅延を生んでいる､と考えられます｡

ノートのサムネールを作成するというDEBUG用の処理がおそらくこのような

タグを解釈しているのでしょう。

普通のWebクリップにも

タグが重層的に含まれる場合がありますが、

2万個も

タグを含むWebページは普通はないので､それなりの遅延が起きているのでしょう｡

結局､DEBUGメッセージを出すような処理を外し忘れているのが､このバグの原因と思われるので､

表面的に言えば､DEBUGメッセージを出さないように修正すれば、遅延が起きなくなるでしょう、たぶん。

米国サイトのフォーラム(英語)を検索してみると､DEBUGメッセージは､かなり以前から出ているので､

Mac版の開発者たちは、DEBUGメッセージを出していることを全く気にしていないようにも見えますが､

少なくとも､常識的に言って､正式リリース版としては普通はあり得ないことです。

仮に、本当に出力すべきメッセージなら、DEBUGという表記を削除すべきですね。

[sugai 0]

追加情報ありがとうございます。

熱心に検証していただけることに感謝いたします。

一方、推測に基づく書き込みはユーザーを混乱させますので、自重していただけると助かります。

開発チームへの報告は上げてますので、具体的な検証は彼らに任せてください。

ご協力ありがとうございます。

[sugai 0]

なぜアクティビティログの場合がこれほど異常な遅延が起きるのかを考えてみると､

アクティビティログのデータ構造が、

　　　

の繰り返し

という単純な構造であることが原因と考えられます｡

EN社への報告のために一応確認させてください。

「

の繰り返し」というのはどういうことでしょう。

アクティビティログをクリップボードにコピーして、それを新規ノートにペーストされているわけですよね。そしてそのノートを.enexに書き出したもの（書き出す際には「各ノートのタグを含める」にチェック）をテキストエディタ等で開いて「

の繰り返し」と確認されているのでしょうか。

もし違う方法でしたら、恐れ入りますが手順のみを簡潔にお願いします。

※追記

補足させていただきますと、テキストだけのノートを上記方法で書き出すと、内容がなんであれDIVタグ区切りになります。アクティビティログだからDIVタグで区切られる……わけではありません。ですので、そのあたり、どのようにご確認されているのか、お伺いしたく思います。私も深く突っ込んで検証できているわけではありませんので。

[KakiShibu 1]

アクティビティログのデータ構造が、

の繰り返しという単純な構造であることが原因、

と推測しましたが、比較不足でした。大変失礼しました。

その後、もう少しよく調べてみたところ、

Win版、Mac版で採取したアクティビティログには大きな違い(一貫性の無さ)があることが分かりました。

Mac内のローカルファイルはファイル名がタイトルそのものではないので見つけるのが大変なので、

ノートのエクスポート(enex形式)で比較しました。

HTML形式のエクスポートやローカルファイルでも違いはないようなので、

enex形式のエクスポートファイルをCodaで読み込んで比較しました。

-----------------------------------------------------------

[Mac版で採取したアクティビティログ]:

　　サイズ: 　　 2.2MB

　　

タグ : 21943個

　　症状:

　　　　・英字モードでの入力は正常

　　　　・ひらがなモードでの入力で15秒の遅延(時々誤入力)

　　　というWebクリップでよく起きる現象(日本語入力のみで5秒以上の遅延や誤入力)のやや重い症状

　　　　・1行(1つのdivタグの範囲)やその一部を選択してCommand+C(あるいはプルダウンメニュー)で

　　　　　コピーしようとすると、1分23秒の無応答になり、復帰する。

-------------

[Win版で採取したアクティビティログ]:

　　サイズ: 　　 2.3MB

　　

タグ : 1個

　　症状:

　　　　・英字モードでもひらがなモードでも、8分以上の異常遅延

　　　　・1行やその一部を選択してコピーしても、特に問題ない。

-----------------------------------------------------------

つまり、これではっきりしたのは、

　・Mac版で採取したアクティビティログとWin版で採取したアクティビティログには、

　　1行ずつ

タグで分割するか・全く分割しないか、

　　というHTMLタグ構造に明らかな違い(仕様の一貫性の無さ)がある。

　・Windows版では、どちらのタグ構造でも特に問題なく正常に動作する。

　・Mac版では、このデータ構造の違いで、症状が大きく変化する。

　・(症状1) 1つの巨大な

タグの中に文字を入力すると、8分以上の異常遅延が起きる。

　・(症状2) 1行ずつ2万個以上の

タグに分割されたものは、15秒以上の比較的軽い遅延や誤入力が起きる。

　　　　　 これは通常のWebクリップの症状に近い。

　・(症状3) 逆に、部分的なコピー動作は、文字入力遅延の軽いタグ構造の方が1分以上の遅延が起きる。

　・もちろん、Coda上で文字を入力したり、部分的なコピー動作をしても、全く問題ない。

結局、2.3MBのほとんど全てが1つの

の内部にあるため、

メモリの確保などに無理がかかっているのかもしれません。

私のMacはメモリ2GBなので、大きくはありませんが、この程度で問題になるとは思えません。

1つの

タグが普通に小さくて数が少ないと5秒以上の遅延が起きて(Webクリップ)、

1つが小さくても2万個も

タグあると15秒以上の遅延が起き、部分的なコピー動作も1分以上かかり、

1つの

タグが2MB以上の巨大な場合は、8分以上の異常遅延になる、

ということです。

小サイズの

タグでも遅延が起きること自体、Mac版の作りには問題がありますが、

そういう作りになっているため、

巨大サイズの

タグでは異常遅延が起きても不思議ではない、と考えられます。

[sugai 0]

ありがとうございます。

アクティビティログにこだわると問題の本質を見誤りそうなので、

アクティビティログ以外の文字列データでどうなるのか、

いちおう私のほうで簡単に検証して追加情報として

EN社に伝えたいと思います。