プロジェクト

全般

プロフィール

バグ #925

mikutterがメモリを大量に消費することがある

Osamu Koga12ヶ月前に追加. 11ヶ月前に更新.

ステータス:
新規
優先度:
通常
担当者:
-
対象バージョン:
開始日:
2016-11-09
プラグイン名:

説明

いわゆるダークマターです。

https://github.com/toshia/memory_profiler/ を入れて1日半程度起動しっぱなしにしておいたmikutter(e1b61877)でグラフを生成したところ、次のグラフが得られました。

この時点でVIRTが20,844,868KB, RESが18,716,708KBとなっています。

Stringの個数が異常に多いので、不要なStringがダブっているのではないかと考えて、以下の手順でダブり数をカウントしました。
  1. GC.start; File.open('/tmp/strings.txt', 'w'){|f| f.puts(ObjectSpace.each_object(String).to_a)} をmikutterコンソールで実行し、生き残っているStringのリストを得る
  2. $ cat /tmp/strings.txt | sort | uniq -c | sort -k1 -r | head -n30 でダブリ個数の上位30件を取ってくる

以下はその結果です。どうもcairoに渡している色コード(詳細不明)と、画像関係っぽい文字列が異常に多く生き残っているようです。

  40392 ja
  31135 fit
  19951 000000
  16739 C0DEED
  15604 https
  15599 twitter.com
  14341 333333
  14159 Tokyo
  12637 none
  10775 
  10378 crop
  10191 DDEEF6
  10129 photo
   9794 https://abs.twimg.com/images/themes/theme1/bg.png
   9794 http://abs.twimg.com/images/themes/theme1/bg.png
   8553 low
   6356 FFFFFF
   6162 0084B4
   4896 recent
   4741 njslyr
   4515 /home/osak/app/mikutter/core/lib/uithreadonly.rb:23:in `block (2 levels) in singleton class'
   3915 /search
   3076 1DA1F2
   2899 <a href="http://twitter.com" rel="nofollow">Twitter Web Client</a>
   2880 en
   2871 http
   2846 pbs.twimg.com
   2780 #njslyr
   2680 mikutter.rb:92:in `<main>'
   2679 mikutter.rb:63:in `boot!'

この時点でのオブジェクト数のうち、メモリやオブジェクトの使用量に相関していそうなものの値は以下の通りでした。
>>> GC.start;ObjectSpace.each_object(Message).count
12605
>>> GC.start;ObjectSpace.each_object(User).reject{|u| Message::MessageUser === u}.count
7738
>>> GC.start;ObjectSpace.each_object(Gtk::TimeLine).reject{|t| t.destroyed?}.count
113
>>> GC.start;ObjectSpace.each_object(Gtk::TimeLine).reject{|t| t.destroyed?}.map(&:size).sort.reverse
[3959, 1243, 1041, 383, 206, 200, 200, 200, 200, 187, 182, 119, 117, 108, 97, 84, 76, 73, 60, 60, 59, 59, 58, 56, 52, 51, 44, 41, 41, 40, 40, 39, 38, 37, 35, 35, 34, 34, 29, 28, 27, 27, 27, 27, 25, 24, 24, 23, 23, 23, 22, 22, 21, 21, 20, 20, 14, 13, 12, 10, 8, 8, 7, 6, 5, 5, 5, 5, 4, 3, 3, 3, 2, 2, 2, 2, 2, 2, 1, 1, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
>>> GC.start;ObjectSpace.each_object(Hash).map(&:size).sort.reverse[0..30]
[41108, 27682, 12673, 7760, 7757, 5096, 4233, 4010, 1620, 1270, 1041, 1017, 918, 811, 498, 485, 436, 383, 383, 379, 373, 373, 348, 327, 327, 310, 291, 273, 262, 256, 253]
>>> GC.start;ObjectSpace.each_object(Gdk::Pixbuf).count
3905
>>> require 'objspace'
GC.start;ObjectSpace.memsize_of_all(String)
164113887
>>> require 'objspace'
GC.start;ObjectSpace.memsize_of_all(Array)
15699400
>>> require 'objspace'
GC.start;ObjectSpace.memsize_of_all(Hash)
159073600

あと入ってるプラグイン一覧:
YUKI.N@aincrad> ls ~/.mikutter/plugin
display_requirements/  memory_profiler/              osa_k_store/        sub_parts_client/
dummy_dep/             mikustore/                    pakuri/             toshi_a_store/
eject/                 mikutter-fb/                  penguin2716_store/  usercomplete/
favorited_count/       mikutter-subparts-image/      protected_source/   userutil/
geocode/               mikutter_shell_post/          randnum/            yukkuri_/
intelligent_fav/       mikutter_update_with_media_/  sakuratrick/
matsuyatter/           mikutter_yodobashi/           shindanmaker/
md5tweet/              nonomura/                     show_tweet/

問題になりそうなものは
  • 単純にMessageが多く、そもそも200個を超えてMessageを保持している謎のGtk::TimeLineがいる(ちなみにプロフィールと抽出タブを合わせて50個くらいタブを開いているので、プロフィール1つにつきTLとDMの2つGtk::TimeLineが生成されることを考えると、TLの個数自体は妥当だと思います)。
  • mikutter内に存在する、意味のある(と想像される)オブジェクト数に対して、異常に巨大なハッシュが存在する
  • スタックトレースの断片のようなものが見える(ただしこれは時間経過で増えないっぽい)

あたりだと思われます。ただそれにしても、memsize_of_allの結果と比べて実際の消費メモリが多すぎるのが少し気になります。
とりあえずはみんなから情報が集まるといいな。

mikutter-memory.png (145 KB) mikutter-memory.png Osamu Koga, 2016-11-04 23:54

子チケット

最適化 #927: 一度も表示されたことのないGtk::TimeLineに追加されたiterがGCされない終了toshi_a 初音

最適化 #930: Message::MessageUserの代わりに新しくUserを作る終了toshi_a 初音


関連するチケット

関連している 環境対応 #933: gtk2 3.1.0を利用する終了2016-11-14

関連している 最適化 #945: Ruby-GNOME2 3.0.9を利用すると、mikutterが消費するメモリが増える終了2016-12-10

履歴

#1 Osamu Koga12ヶ月前に更新

明らかにGdk::Pixbufが漏れており、バカにならない容量を食っているようです。

>>> GC.start;ObjectSpace.each_object(Gdk::MiraclePainter).select{|m| m.instance_eval{@pixbuf}}.count
1194
>>> GC.start;ObjectSpace.each_object(Gdk::Pixbuf).count
3852
>>> GC.start;
mp_buf = Set[*ObjectSpace.each_object(Gdk::MiraclePainter).map{|m| m.instance_eval{@pixbuf}}.compact]
ObjectSpace.each_object(Gdk::Pixbuf).reject{|p| mp_buf.include?(p)}.reduce(0){|a,b| a + b.width*b.height*b.bits_per_sample/8*b.n_channels}
1245595332

これと関連して、同じようなオブジェクトが大量にゾンビ化するひとつの原因として、長生きするクロージャを作った時に不要なローカル変数を巻き込んでしまっている可能性があるのではないかと思いました。File.open('/tmp/procs.txt', 'w'){|f| f.puts(ObjectSpace.each_object(Proc).map(&:source_location).reject(&:nil?).map{|a| a.join(' ')})} の結果をStringと同様に集計すると、結構たくさん出てきます(一番上はssc)。

  41534 /home/osak/app/mikutter/core/mui/gtk_extension.rb 28
  10520 /home/osak/app/mikutter/core/mui/cairo_inner_tl.rb 198
   6874 /home/osak/app/mikutter/core/mui/cairo_sub_parts_voter.rb 52
   6874 /home/osak/app/mikutter/core/mui/cairo_sub_parts_voter.rb 32
   6874 /home/osak/app/mikutter/core/mui/cairo_sub_parts_voter.rb 17
   1781 /home/osak/.mikutter/plugin/sub_parts_client/sub_parts_client.rb 15
   1781 /home/osak/.mikutter/plugin/geocode/geocode.rb 14
   1776 /home/osak/app/mikutter/core/mui/cairo_coordinate_module.rb 85
   1773 /home/osak/app/mikutter/core/mui/cairo_coordinate_module.rb 91
   1439 /home/osak/.gem/gems/gobject-introspection-3.0.9/lib/gobject-introspection/loader.rb 553
   1439 /home/osak/.gem/gems/gobject-introspection-3.0.9/lib/gobject-introspection/loader.rb 547
    633 /home/osak/app/mikutter/core/lib/uithreadonly.rb 20
    530 /home/osak/app/mikutter/core/mui/cairo_sub_parts_message_base.rb 180
    477 /home/osak/.mikutter/plugin/mikutter-subparts-image/mikutter-subparts-image.rb 72
    448 /home/osak/.mikutter/plugin/mikutter-subparts-image/mikutter-subparts-image.rb 151
    448 /home/osak/.mikutter/plugin/mikutter-subparts-image/mikutter-subparts-image.rb 134
    448 /home/osak/.mikutter/plugin/mikutter-subparts-image/mikutter-subparts-image.rb 116
    292 /home/osak/app/mikutter/core/plugin/gtk/gtk.rb 490
    292 /home/osak/app/mikutter/core/plugin/gtk/gtk.rb 149
    292 /home/osak/app/mikutter/core/plugin/gtk/gtk.rb 142
    292 /home/osak/app/mikutter/core/plugin/gtk/gtk.rb 140
    292 /home/osak/app/mikutter/core/plugin/gtk/gtk.rb 136
    237 /home/osak/app/mikutter/core/mui/gtk_tree_view_pretty_scroll.rb 31
    237 /home/osak/app/mikutter/core/mui/gtk_tree_view_pretty_scroll.rb 16
    234 /home/osak/app/mikutter/core/plugin/gui/gui.rb 58
    234 /home/osak/app/mikutter/core/plugin/gui/gui.rb 52
    232 /home/osak/app/mikutter/core/mui/gtk_tree_view_pretty_scroll.rb 20
    222 /home/osak/.gem/gems/gobject-introspection-3.0.9/lib/gobject-introspection/loader.rb 255
    166 /home/osak/.gem/gems/gobject-introspection-3.0.9/lib/gobject-introspection/loader.rb 109
    166 /home/osak/.gem/gems/gobject-introspection-3.0.9/lib/gobject-introspection/loader.rb 103

mikutter-subparts-image.rbも上の方にいるので、画像のpixbufをsscに巻き込んでしまっているのかなという気がします。

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

TimelineがPixbuf、恐らくMiraclePainterを解放してない問題ですね。MiraclePainterにはそういう問題が存在している気がしていたので、これで証拠としては十分出たと思います。OSC終わったらこちらでも検証してみますね

#3 Osamu Koga11ヶ月前に更新

#927 を適用&mikutter-subparts-imageを外した状態でも、速度は遅いもののやはりじわじわとメモリ使用量が上がっていきます(約3日でVIRT10.2G / RES8.0G程度)。ただ、最初の報告時の倍の時間起動しっぱなしにしているにも関わらず、重複している文字列の個数は以前とそんなに変わっていません。

$ cat /tmp/strings.txt | sort | uniq -c | sort -k1 -r | head -n30
  39550 fit
  38585 ja
  22407 C0DEED
  21929 000000
  18472 333333
  16522 Tokyo
  16148 none
  13183 crop
  13129 DDEEF6
  13051 photo
  12582 https
  12580 twitter.com
  11485 https://abs.twimg.com/images/themes/theme1/bg.png
  11485 http://abs.twimg.com/images/themes/theme1/bg.png
  10851
   9043 1DA1F2
   8145 FFFFFF
   8140 low
   8131 /home/osak/app/mikutter/core/lib/uithreadonly.rb:23:in `block (2 levels) in singleton class'
   4716 219566976
   4285 /home/osak/app/mikutter/core/mui/gtk_extension.rb:34:in `block in safety_signal_connect'
   4134 njslyr
   4030 mikutter.rb:92:in `<main>'
   4030 mikutter.rb:63:in `boot!'
   4030 /home/osak/app/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
   4030 /home/osak/app/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
   3971 und
   3755 http
   3729 pbs.twimg.com
   3563 recent

最初の投稿とほぼ同じような内容ですが、 #927 を適用しているにも関わらず、ニンジャスレイヤー関連の文字列(njslyr、219566976(@shonen_siriusのUser IDで、#njslyrタグを使ってニンジャスレイヤーのコミカライズを投稿している))が異常に多いのが気になります。ニンジャスレイヤー情報はSaved Searchとリストを使って追っているのですが、このへんの処理がおかしくて解放できていない何かがあるんじゃないかと思います。

#4 toshi_a 初音11ヶ月前に更新

listはUIをextractに任せているので、独自にUIを持っているsaved_searchが怪しい気がしますね。
こっちでも同じ方法で計測して、そんな感じの結果が出るかどうか試してみます

#5 toshi_a 初音11ヶ月前に更新

#6 toshi_a 初音11ヶ月前に更新

  • 関連している 最適化 #945: Ruby-GNOME2 3.0.9を利用すると、mikutterが消費するメモリが増える を追加

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