Where communities thrive


  • Join over 1.5M+ people
  • Join over 100K+ communities
  • Free without limits
  • Create your own community
People
Activity
    dodaisuke
    @dodaisuke
    history.png
    なお、PostgreSQLのデータファイルは別領域に配置しているため、/領域が使われていく理由がよく分かっていません。。(コアダンプが一時的に/var/spoolに吐き出されて圧迫された?ファイルがなさそうなので何が起きたのか把握できておりません。。)
    上記の情報までになりますが、何かこの点を調査した方が良い、などありましたらアドバイスいただけますと有難いです。
    よろしくお願いいたします。
    dodaisuke
    @dodaisuke

    なお、本番環境は
    ・CentOS6
    ・PostgreSQL9.5.15
    ・pgroonga2.1.6

    ・CPU16core
    ・Mem96GB
    ・500GB SSD
    ※このスペックが出る仮想マシンとの触れ込みです。

    となります。よろしくお願いいたします。

    Sutou Kouhei
    @kou
    たしかにディスク容量が減っていくのは変ですね。
    コアが出力されたのが原因なら06:36:13以降に減っていきそうですが、06:35:30ちょい前から減っているのが妙ですね。
    06:52:30ちょい前から使えるディスク領域が増えていっていますが、このときには何をしたかわかりますか?
    06:52:43にPostgreSQLが起動しているのでPostgreSQLの再起動かしら。
    Sutou Kouhei
    @kou
    PGroongaのバックトレースがでてからPostgreSQLのマスタープロセスがPGroongaのプロセスのクラッシュを検出しているのが06:52:43なのでコアを吐いていたけどディスクがなくなったので諦めて死んだ、という感じかしら。
    でも、こいつが動く前からディスクが使われて始めているのでそれは妙なんですよねぇ。
    dodaisuke
    @dodaisuke
    06:52:30ちょい前から使えるディスク領域が増えていっていますが、このときには何をしたかわかりますか?
    06:52:43にPostgreSQLが起動しているのでPostgreSQLの再起動かしら。
    こちらも想像でしかないのですが、おそらくPostgreSQLの再起動かな、と考えています。。
    (それでも/領域、という点が解せないのですが。。)
    abrtdが動いているため、コアを消して回っている可能性もあるのですが、/var/log/messagesを見る限りそのような動きはないのですよね。。ログを書けるスペースがなかった、という話もあるかもしれないのですが。。

    クラッシュを検出しているのが06:52:43なのでコアを吐いていたけどディスクがなくなったので諦めて死んだ

    はい、この可能性も高いと見ています。
    問題への対処方法として単に/領域の容量を増やせば良いのか(そしてどの程度増やせば良いのか)という点が見えなくてどうすべきか。。という感じです。。

    dodaisuke
    @dodaisuke
    検証環境も本番とバッチ処理等同じアプリケーションが動いているのですが、そこで再現しない点が厳しいところです。。
    ※本番で実験はできないので、、
    dodaisuke
    @dodaisuke
    今は、検証環境のPostgreSQLが9.1.14、本番環境のバージョンが9.1.15だったため、検証環境の枝番を上げて様子を見てみようとしています。
    それ以外には本番環境のCentOSが6.8、検証環境が6.9の違いがあるのですが、ここはちょっと実験が難しいところです。。
    Sutou Kouhei
    @kou
    コアは最大でもそのプロセスが確保しているメモリー(仮想メモリーも含む)と同じくらいなので、100GBもあればコアは吐けると思います。
    dodaisuke
    @dodaisuke
    なるほどです!契約しているVMの性質上、/領域を30GB以上にすることができないので(汗、コアを吐く場所を変更するとひとまずディスクの問題は回避できそうですね。
    dodaisuke
    @dodaisuke
    ちなみに、/領域のディスクスペース不足とPGroongaのクラッシュの関連性で、考え得ることはありますでしょうか?
    クラッシュはディスクスペースが0になる前ですが、仮にダンプ等によりOS側が認識するアロケートできるメモリが枯渇し、PGroongaなりがアロケートしようとした場合にもう確保できない、などといったことです。
    たしかアロケートできない場合はその旨ログが出たように記憶しているので、クラッシュする要因ではないように思いますが、その認識は合っていますでしょうか。。
    Sutou Kouhei
    @kou
    そうですね。アロケートできなければログに出ますね。
    クラッシュは(オートバキュームの)レコード削除にともなうインデックス更新で発生しているんですが、これがディスクスペースと関係するとは思えないんですよねぇ。同じ処理をしているなら、本番環境でも検証環境でも発生すると思うんですよねぇ。
    dodaisuke
    @dodaisuke

    ありがとうございます、やはりアロケートに関してはログが出ますよね。認識合っていて良かったです。

    (オートバキュームの)レコード削除にともなうインデックス更新で発生している

    確かにその処理でしたら検証環境でも同じことをやりますので、今までに発生していておかしくないのですよね。。
    (なのでこちらもなぜ検証環境で発生しないのか、が理解できず・・)
    ふぅむ、、今のところあまり良いアイディアはないのですが引き続き色々と調査検討してみます。。

    dodaisuke
    @dodaisuke
    なんとか検証環境で再現できました。大量にゴミが出るような処理を行っていると、auto vacuum後?にクラッシュが発生するようです。
    2018-12-06 17:35:01.163831|n|7700: grn_init: <8.0.9>
    2018-12-06 17:35:01.163947|n|7700: vm.overcommit_memory kernel parameter should be 1: <2>: See INFO level log to resolve this
    2018-12-06 17:35:01.164142|n|7700: pgroonga: initialize: <2.1.6>
    2018-12-06 17:35:01.203817|C|7700: -- CRASHED!!! --
    2018-12-06 17:35:01.227258|C|7700: /usr/lib64/libgroonga.so.0(+0x11f7a7) [0x7f614dade7a7]
    2018-12-06 17:35:01.227287|C|7700: /lib64/libc.so.6() [0x3ee0e32510]
    2018-12-06 17:35:01.227293|C|7700: postgres: postgres waja [local] SELECT(pfree+0xb) [0x7cd1ab]
    2018-12-06 17:35:01.227298|C|7700: /usr/pgsql-9.5/lib/pgroonga.so(+0x117ff) [0x7f614e5187ff]
    2018-12-06 17:35:01.227303|C|7700: /usr/pgsql-9.5/lib/pgroonga.so(+0x1196f) [0x7f614e51896f]
    2018-12-06 17:35:01.227308|C|7700: postgres: postgres waja [local] SELECT() [0x7cfc2f]
    2018-12-06 17:35:01.227313|C|7700: postgres: postgres waja [local] SELECT() [0x7cfbd2]
    2018-12-06 17:35:01.227318|C|7700: postgres: postgres waja [local] SELECT(ResourceOwnerRelease+0x70) [0x7d0050]
    2018-12-06 17:35:01.227322|C|7700: postgres: postgres waja [local] SELECT() [0x4cb607]
    2018-12-06 17:35:01.227327|C|7700: postgres: postgres waja [local] SELECT(AbortCurrentTransaction+0x25) [0x4cbcb5]
    2018-12-06 17:35:01.227332|C|7700: postgres: postgres waja [local] SELECT(PostgresMain+0xbcd) [0x6bf88d]
    2018-12-06 17:35:01.227337|C|7700: postgres: postgres waja [local] SELECT(PostmasterMain+0x1885) [0x665455]
    2018-12-06 17:35:01.227342|C|7700: postgres: postgres waja [local] SELECT(main+0x7a8) [0x5f6788]
    2018-12-06 17:35:01.227347|C|7700: /lib64/libc.so.6(__libc_start_main+0xfd) [0x3ee0e1ed1d]
    2018-12-06 17:35:01.227351|C|7700: postgres: postgres waja [local] SELECT() [0x4679b9]
    2018-12-06 17:35:01.227357|C|7700: ----------------
    <2018-12-06 17:35:01.203 JST>[d:waja r:[local] p:7700 c:5c08df35.1e14 l:1 s:2018-12-06 17:35:01 JST v:60/62960 x:0]ERROR:  tuple offset out of range: 42134
    <2018-12-06 17:35:01.203 JST>[d:waja r:[local] p:7700 c:5c08df35.1e14 l:2 s:2018-12-06 17:35:01 JST v:60/62960 x:0]STATEMENT:  SELECT pgroonga_score(tableoid, ctid) as roonga_score, id, brand_id, brand_name_jp, brand_name_en, seo_name_flg, line_id, belong_brand_id, belong_brand_name_jp, belong_brand_name_en, belong_brand_seo_name_flg, belong_brand_line_id, seller_id, seller, genre_id, genre, country_code, country, name, suggested_price, enable, status, area_id, area, last_arrival_date, max_off, max_off_percent, seller_status, coupon_back_id, coupon_back_percent, coupon_back_expire_date, coupon_back_issue_date, coupon_back_min_price, waja_coupon_back_id, waja_coupon_back_percent, waja_coupon_back_expire_date, page_view, size_on_tag_web_names, color_ids, latest_expire_date, last_expire_date, sale_flg, genre_names, entry_statuses, market_place_id, sample_product_flg, seller_product_price, variation_count, size_on_tag_web_names_sold, selling_reserve_item_count, selling_item_count, disp_item_count, sold_item_count, sold_reserve_item_count, season, season_year, season, grade_b, tids, wish_item_count, cart_item_count, score, original_product_entry_count,variation_number, album_code, image_random_code
            from product_view_stg  where enable=true and ARRAY [name, seller_comment, material, country, size_on_tag_web_names, genre_names, belong_brand_name_jp, belong_brand_name_en] &@~ pgroonga_query_expand('synonyms', 'term', 'synonyms','ロング') and status = 1 and genre_id in ('133','741','516','517','262','264','263','261','260','693','680','271','265','690','692','691','687','689','688','550','557','337','339','513','551','575','338','698','761','558','555','556','515','554','340','514','694','565','537','536','341','545','566','342') and secret_sale_id <= 0  order by (suggested_price - max_off) desc, id desc limit 120 offset 0;
    <2018-12-06 17:35:04.485 JST>[d:waja r:192.168.2.12(48298) p:7491 c:5c08de16.1d43 l:3 s:2018-12-06 17:30:14 JST v:17/117339 x:0]LOG:  duration: 4177.058 ms  execute <unnamed>: select id, pattern.score_pattern, seller_id, last_arrival_date, belong_brand_id, selling_item_count, disp_item_count, sold_item_count, size_on_tag_web_names, variation_count, original_product_entry_count, market_place_id, suggested_price, seller_product_price, max_off, ps.score FROM product_view_stg p LEFT JOIN product_score ps ON (p.id = ps.product_id), (SELECT DISTINCT score_pattern FROM score_weight WHERE score_pattern <> 'NONE') pattern WHERE ps.score IS NULL
    <2018-12-06 17:35:43.323 JST>[d: r: p:23968 c:5c088b29.5da0 l:4 s:2018-12-06 11:36:25 JST v: x:0]LOG:  server process (PID 7700) was terminated by signal 6: Aborted
    ※この後PostgreSQLがリカバリモードに移行してしまいます。
    ログの見え方としては先日Groongaで修正いただいた「削除したレコードにヒットしている」ような見え方でしょうか。
    追加情報等、必要でしたら教えてください、お手数ですがよろしくお願いいたします。
    dodaisuke
    @dodaisuke
    ※今のところ「それっぽい現象が再現できた」のみで、100%再現する方法があるわけではありません。念のため。。
    dodaisuke
    @dodaisuke
    同じようなことを何度かやっていると発生しますので、一応再現させることは可能、という状況です。
    Sutou Kouhei
    @kou
    うーん、これは落ち方が違いますね。。。
    これはPGroongaのmasterですか?2.1.6ですか?2.1.6ならmasterでは直っているやつだと思います。
    dodaisuke
    @dodaisuke
    あらら、、違いましたか・・
    こちらはyumでインストールしたバージョンになります!
    となると、本番でもmasterをビルドして使った方が良かった、ということになりますかね。。
    Sutou Kouhei
    @kou
    そうですね。
    今月中にリリースしたいなぁとは思っています。
    dodaisuke
    @dodaisuke
    おっと、失礼しました
    となると、ひとまずmasterビルド方向で本番再投入も検討します!
    kenjiuno
    @kenjiuno

    PGroonga 2.1.6 pgroonga-2.1.6-postgresql-9.6.10-1-x86.zip を PostgreSQL 9.6 (x86) Windows で利用させて頂いています。(恐らくバイグラム方式 ? で使用中)

    インデックス持ちの TABLENAME へ UPDATE 発行すると grn_io_lock failed エラーが発生してしまいます。ポスグレを再起動しても改善しませんでした。

    2018-11-28 12:29:22 JST ERROR:  pgroonga: failed to add a record: <64u>: grn_io_lock failed
    2018-11-28 12:29:22 JST STATEMENT:  UPDATE TABLENAME set getcount = COALESCE(getcount, 0) + 1 where id = $1

    ※ pgroonga.log を見ると… x86 のメモリ上限に由来すると思われる大量のエラー 例 system error[8]: このコマンドを実行するための十分な記憶域がありません。: MapViewOfFile(121700352,4194304) failed <1481965568> が記録されているので、ロックが残っている可能性を思案しました。

    google で調べてみると「ロックが刺さる」という現象があるそうでして… このロックの有無を確かめる方法ってありませんでしょうか。

    ロックを包括的に解除するコマンドはあるようなのですが… http://groonga.org/ja/docs/reference/commands/lock_clear.html

    Sutou Kouhei
    @kou
    ロックが残っていると思うので、PostgreSQLを終了してデータディレクトリーのpgn*ファイルを全部削除してから起動してRECREATE INDEXしてください。
    kenjiuno
    @kenjiuno

    ありがとうございます。

    PostgreSQLを終了してデータディレクトリーのpgn*ファイルを全部削除

    del pgrn* /s で削除しました。

    起動してRECREATE INDEX

    えっと念のため確認です。どちらでしょうか…

    reindex database DB
    drop index / create index

    一 応再現環境は確保できていますので、テストは何でもできます。 postgres.exe --single で起動して、 reindex database しました。

    backend> reindex database dd
    2018-12-07 12:46:46 JST ERROR:  pgroonga: failed to set column value: [ja][lz4] failed to allocate compress buffer: <BuildingSources2010572.ddstrnormalizer>: <288485>
    2018-12-07 12:46:46 JST STATEMENT:  reindex database dd

    むむ何やらエラーが…

    その後 insert を実行するとエラーに…

    backend> insert into dd_drawingplan (id) values ('test');
    2018-12-07 12:49:05 JST ERROR:  pgroonga: object isn't found: <Sources1896277>
    2018-12-07 12:49:05 JST STATEMENT:  insert into dd_drawingplan (id) values ('test');
    Sutou Kouhei
    @kou
    あぁ、すみません。REINDEXです。
    そもそもメモリーが足りないような気がします。
    kenjiuno
    @kenjiuno

    なるほど…
    こちらでは再現方法を模索するべく reindex / drop index / create index を乱発してみましたが…
    同じ postgres backend に対して reindex を実行し続けると「いずれ詰む」という結果でした。

    CREATE INDEX index_1 (...);
    CREATE INDEX index_2 (...);
    CREATE INDEX index_3 (...);

    のようにインデックスの名前だけ変更して、同じインデックスを延々と作成し続けると止まる瞬間が来る、という事です…

    ああ reindex ではありませんでした m(__)m
    2018-12-07 13:50:21 JST ERROR:  pgroonga: failed to set sources: <Lexicon2017827_0.index>: <[297]>: system error[8]: このコマンドを処理するにはメモリ リソースが足りません。: MapViewOfFile(125894656,41
    2018-12-07 13:50:21 JST STATEMENT:  CREATE INDEX dd_drawingplan_idx_fts1body_3
            ON public.dd_drawingplan USING pgroonga
            (ddstrnormalizer(fts1body) COLLATE pg_catalog."default")
            TABLESPACE pg_default;
    kenjiuno
    @kenjiuno
    あくまで仮説なので… 検証はして参ります…
    dodaisuke
    @dodaisuke
    PGroongaのmasterの最新をビルドし(ログ上には2.1.7と表示されます)、Groonga 8.0.9を利用し、テーブルの更新処理が忙しいときに以下のエラーが出ることが確認できました。
    <2018-12-07 14:23:01.124 JST>[d:waja r:[local] p:4261 c:5c0a03b5.10a5 l:1 s:2018-12-07 14:23:01 JST v:71/15874 x:0]ERROR:  tuple offset out of range: 448
    クラッシュは発生しません。
    なお、該当のインデックスをREINDEXすると正しく処理されるようになります。
    何かこちらでできることはありますでしょうか・・
    よろしくお願いいたします。
    Sutou Kouhei
    @kou
    @kenjiuno PostgreSQLはVACUUMするまで古いものを消さないのでCREATE INDEXをし続けるとリソースを食いつぶします。(PGroongaの場合は仮想メモリーも減りますけど、PostgreSQLだけでもディスク領域とか減っていく一方です。)
    単にテストでやっているだけで実際はそんな風に使わないですよね?
    普通はオートバキュームが動いて食いつぶすことはないはずです。
    仮想メモリーが減っていくことだけが問題ならPostgreSQLに接続しなおせば解放されます。
    @dodaisuke うーん、前にやってもらったようにデバッグレベルにしてログをとってもらえますか?
    dodaisuke
    @dodaisuke
    @kou 了解です!githubにissue作ってレポートすれば良いでしょうか?
    それともこちらにひとまずアップすれば良いでしょうか。
    Sutou Kouhei
    @kou
    issueを作りましょう!
    dodaisuke
    @dodaisuke
    はい、ありがとうございます!
    dodaisuke
    @dodaisuke
    先ほどissueを作成しました。お手数ですがよろしくお願いします。