プロジェクト

全般

プロフィール

致命的 #995

CPU使用率が常に100%になり、メモリを大量に確保しつづけることがある

toshi_a 初音2ヶ月前に追加. 5日前に更新.

ステータス:
進行中
優先度:
通常
担当者:
対象バージョン:
開始日:
2017-03-16
期日:
進捗率:

0%

プラグイン名:
バックトレース:

なし

再現手順:

不明


説明

CPU使用率が100%となり、使用メモリは毎秒+100MBくらいのペースで増加する。この間、多少動作が重いがmikutterのUIを操作することは出来る。
発生条件は不明で、発生するときは5分くらい使っていたら発生するし、しないときは数日再現しないことがある。

Delayer Deferred 1.1.0にしてから発生するようになったと思われる。プラグインでSample Streamを受信するなどしても発生頻度は変わっていないようなので、ある種類のツイートがトリガーになっているというわけでもないかもしれない。
私以外誰も再現していないようなので優先度は下げるが、この状態になれば数分以内にメモリを食い尽くしてクラッシュするので、致命的な問題として取り扱う。

他に再現した人がいたら、新たなことが分からなくても良いので、このチケットにコメントを残してください。

スクリーンショット 2017-05-21 18.30.58.png 表示 (406 KB) あひる 家鴨, 2017-05-21 18:41

スクリーンショット 2017-05-21 18.31.15.png 表示 (374 KB) あひる 家鴨, 2017-05-21 18:41


関連するチケット

ブロック先 バグ #916: 定期的にfollowアクティビティが大量に生成される 進行中 2016-10-11

関係しているリビジョン

リビジョン 4fb3ba5b (差分)
toshi_a 初音5日前に追加

Delayer Deferred 2系を利用 refs #995

履歴

#1 toshi_a 初音約2ヶ月前に更新

  • ブロック先 バグ #916: 定期的にfollowアクティビティが大量に生成される を追加

#2 toshi_a 初音約2ヶ月前に更新

  • ステータス新規 から 進行中 に変更

どうやらdelayer-deferredの不正な使い方が問題なのではないかと考えた。

現在のdelayer-deferredはJavaScriptのものをほとんど直訳しただけで、nextメソッドを同じDeferredに対して複数回呼ぶなどの不正な操作を受け付けてしまい、その際の動作が未定義だった。
大幅に書き直したdeferred 2.0を試作して、mikutterにそちらを利用させることで詳細なエラーを得て、3.5にもフィードバックしたい。

#3 toshi_a 初音約2ヶ月前に更新

deferred 2.0を利用したところ、起動直後に以下のようなエラーでクラッシュする。

/home/toshi/Projects/delayer-deferred/lib/delayer/deferred/deferredable/node_sequence.rb:29:in `pull': Invalid sequence flow `stop' to `await'.
     from /home/toshi/Projects/delayer-deferred/lib/delayer/deferred/deferredable/node_sequence.rb:122:in `change_sequence'
     from /home/toshi/Projects/delayer-deferred/lib/delayer/deferred/deferredable/awaitable.rb:20:in `enter_await'
     from /home/toshi/Projects/delayer-deferred/lib/delayer/deferred/request.rb:38:in `accept_request'
     from /home/toshi/Projects/delayer-deferred/lib/delayer/deferred/worker.rb:34:in `block in push'
     from /home/toshi/Projects/mikutter/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
     from /home/toshi/Projects/mikutter/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
     from /home/toshi/Projects/mikutter/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
     from /home/toshi/Projects/mikutter/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
     from /home/toshi/Projects/mikutter/core/plugin/gtk/delayer.rb:10:in `block in boot'
     from /home/toshi/Projects/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
     from /home/toshi/Projects/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
     from /home/toshi/Projects/mikutter/mikutter.rb:67:in `boot!'
     from /home/toshi/Projects/mikutter/mikutter.rb:96:in `<main>'

2.0ではDeferredチェインベースのバックトレースも生成できるので、こういう時にそれが出力できたほうが良さそう

#4 Akira Ouchi7日前に更新

再現を確認できました。
  • Mac OS X 10.10.5
  • ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-darwin14]
  • mikutter hotfix/3.5 branch commit ce152e52a44c691ed55317a44192513fa94c5b54

Gemfileで1.0.4にバージョン固定にしてやると回避できました。(再現を試すときは1.1.1で固定)

#  gem 'delayer-deferred', '>= 1.0.4', '< 2.0'
#  gem 'delayer-deferred', '1.1.1'
  gem 'delayer-deferred', '1.0.4'

参考になるのかわからないですが、起動後にCtrl+Cで終了させた時の出力を貼っておきます。

notice: {MIKUTTER_DIR}/core/configloader.rb:32:in `block in <module:ConfigLoader>': configloader: wrote 4 keys (Plugin::saved_search_last_saved_search_state, UserConfig::extract_tabs, UserConfig::ui_tab_order, UserConfig::profile_opened_tabs)
error: /Users/akkie/.mikutter/plugin/slack/api/realtime.rb:50:in `block in connected': 784: unexpected token at 'You are sending too many requests. Please relax.'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/json_pure-1.8.6/lib/json/common.rb:155:in `parse'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/json_pure-1.8.6/lib/json/common.rb:155:in `parse'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response/parse_json.rb:11:in `block in <class:ParseJson>'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response_middleware.rb:48:in `parse'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response_middleware.rb:39:in `process_response'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response_middleware.rb:32:in `block in call'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/response.rb:61:in `on_complete'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response_middleware.rb:30:in `call'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/request/url_encoded.rb:15:in `call'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/request/multipart.rb:15:in `call'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/rack_builder.rb:139:in `build_response'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/connection.rb:386:in `run_request'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/faraday-0.12.1/lib/faraday/connection.rb:186:in `post'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/slack-api-1.3.0/lib/slack/request.rb:29:in `request'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/slack-api-1.3.0/lib/slack/request.rb:11:in `post'
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/slack-api-1.3.0/lib/slack/endpoint/users.rb:67:in `users_list'
from /Users/akkie/.mikutter/plugin/slack/api.rb:32:in `block in users'
warning: {MIKUTTER_DIR}/core/lib/reserver.rb:72:in `rescue in block (2 levels) in waiter': undefined method `each' for nil:NilClass
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/2.3.0/set.rb:674:in `each'
from {MIKUTTER_DIR}/core/lib/reserver.rb:62:in `first'
from {MIKUTTER_DIR}/core/lib/reserver.rb:62:in `block (2 levels) in waiter'
warning: {MIKUTTER_DIR}/core/lib/reserver.rb:72:in `rescue in block (2 levels) in waiter': undefined method `each' for nil:NilClass
from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/2.3.0/set.rb:674:in `each'
from {MIKUTTER_DIR}/core/lib/reserver.rb:62:in `first'
from {MIKUTTER_DIR}/core/lib/reserver.rb:62:in `block (2 levels) in waiter'
notice: {MIKUTTER_DIR}/core/plugin/streaming/filter.rb:62:in `block (2 levels) in start': retry wait 0, fail_count 0
^C/Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/extend.rb:127:in `lock': Interrupt
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/priority.rb:34:in `register'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:11:in `initialize'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:49:in `new'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:49:in `initialize'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:68:in `new'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:68:in `_call'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:29:in `fail'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:156:in `_fail_action'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:120:in `_fiber_completed'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:87:in `block in _call'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
     from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
     from /Users/akkie/mikutter/core/plugin/gtk/delayer.rb:10:in `block in boot'
     from /Users/akkie/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
     from /Users/akkie/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
     from mikutter.rb:67:in `boot!'
     from mikutter.rb:96:in `<main>'
notice: mikutter.rb:73:in `rescue in boot!': catch exception `SystemExit'
notice: mikutter.rb:75:in `rescue in boot!': => `SystemExit'
notice: mikutter.rb:100:in `rescue in <main>': catch SystemExit
notice: mikutter.rb:84:in `error_handling!': catch Interrupt
/Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/priority.rb:34:in `register': Interrupt
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:11:in `initialize'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:49:in `new'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:49:in `initialize'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:68:in `new'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:68:in `_call'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:29:in `fail'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:156:in `_fail_action'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:120:in `_fiber_completed'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-deferred-1.1.1/lib/delayer/deferred/deferredable.rb:87:in `block in _call'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
    from /Users/akkie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
    from /Users/akkie/mikutter/core/plugin/gtk/delayer.rb:10:in `block in boot'
    from /Users/akkie/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
    from /Users/akkie/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
    from mikutter.rb:67:in `boot!'
    from mikutter.rb:96:in `<main>'

#5 toshi_a 初音7日前に更新

  • 優先度低め から 通常 に変更

他の環境で再現できたということなので本格的に対応を始めます。
やはりDeferred 1.1とmikutter 3.5以降の組み合わせで確定かと思います。現在Deferred 2を使って修正中なので、修正が完了したら再現テストをお願いすると思います。
他にも再現した人が居たら、引き続き情報お願いします

#6 あひる 家鴨7日前に更新

再現しました
macOS 10.12.4
ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-darwin16]
develop branch 33e70f7e06914e046a1d2a055f6d157d37f3167a
delayer-deferred (1.1.1)

ruby については 85 ~ 97 % あたりを常にうろうろしていて、メモリの使用量はどんどん増えていく感じです
メモリに関しては書いている時点で 14 GB /16 GB ほど持って行かれているので16になるまで観察します。

#7 toshi_a 初音6日前に更新

@ahiru まあ観察はいいですよ。このあとチケットに追記しますが、このバグ修正はほぼ終わっているので、それを公開したら、その修正のテストを手伝ってください。今のところは、再現手順を確立してもらえばそれで十分なので、delayer 1.0系に戻して普段は過ごしてください。
このバグは1/3ゆゆ式程度(7分強)の時間で発生することが多いので、念の為ゆゆ式を視聴しながら確実に再現できるかどうか確認しておいてもらえるとありがたいです。

#8 toshi_a 初音5日前に更新

Delayer Deferred 2.0を使えば手元の環境でも問題が起こらないことを確認しました。
ひとまず、 topic/995-deferred-2 というbranchで問題が再現しないか確認してもらえますか。

ただ、ライブラリのメジャーバージョンを上げるのはmikutter 3.6からにしようと思っているので、3.5のためにDelayer Deferred 1.1でも原因を特定して修正する必要があります。

#9 Akira Ouchi5日前に更新

#995-8 の環境に切り替えて再現の確認中です。1/3ゆゆ式を過ぎてもとくに問題ないようです。

他の形式にエクスポート: Atom PDF