Bug #1802

FULLTEXT initializationについて

Added by Kentoku SHIBA almost 5 years ago. Updated over 4 years ago.

Status:担当者作業中Start date:07/05/2013
Priority:NormalDue date:
Assignee:Kouhei Sutou% Done:

80%

Category:-
Target version:-

Description

いつもお世話になっております。

■概要■

mroongaで、1つのSQLにてマッチした行数を返すタイプの検索を
大量に行っております。
現在、かなり高速に検索できているのですが、更に高速化したいので
お知恵をお借りできれば幸いです。

■背景■

mroongaをインストールしたマシンに、単一のDBを作成し、
単一のmroongaテーブルを作成して使用しています。

テーブルは検索にのみ使用し、insert/delete/update等は一切行いません。

テーブルサイズは4GBで、メモリは32GBです。
CPUはCorei7で、仮想的に8CPUとして見えています。

ユーザーレベルで上げているサービスはmysqldだけです。

/etc/my.cnf
にて
innodb_buffer_pool_size = 8G
を指定しており、mroongaのデータは
該当ディレクトリにて
cat * > /dev/null
して、メモリキャッシュに乗せてあります。

この状態で
vmstat -S m 5 5
すると、下記のようになります。

[k-isobe@PMJ41 ~]$ vmstat -S m 5 5
procs -----------memory---------- ---swap-- -----io---- --system--
-----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
6 0 0 25569 3 4683 0 0 0 2 0 4 19 4 77 0 0
7 0 0 25478 3 4683 0 0 0 0 342832 96052 50 11 40 0 0
8 0 0 25370 3 4683 0 0 0 0 266249 72371 67 8 26 0 0
13 0 0 25438 3 4683 0 0 0 0 293404 89771 56 10 34 0 0
8 0 0 25608 3 4683 0 0 0 0 340593 91199 54 10 36 0 0
[k-isobe@PMJ41 ~]$

物凄く大量のin/csが発生しており、大量の処理をこなしているのが見て取れます。
また、データがオンメモリで、かつ、検索だけなので
bi bo共に0で、DBとしてはかなり良好な状態だと考えています。

この状態でmysqldのCPU使用率は下記のように442%となっています。
CPUが8個あるので、CPU使用率的には800%まで上がる訳ですよね・・・

[k-isobe@PMJ41 ~]$ ps u -www -C mysqld
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
mysql 18109 442 11.3 21175916 3721212 pts/0 Sl 17:17 540:07
/usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql
--plugin-dir=/usr/lib64/mysql/plugin --user=mysql
--log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid
--socket=/tmp/mysql.sock --port=3306
[k-isobe@PMJ41 ~]$

一方、MySQLが何をやっているかを調べると、下記のようになっていました。

[k-isobe@PMJ41 ~]$ echo 'show processlist' | mysql -u root mysql | wc -l
71
[k-isobe@PMJ41 ~]$ echo 'show processlist' | mysql -u root mysql | egrep
-v 'State|NULL' | cut -f 7 | sort | uniq -c | sort -nr
40 FULLTEXT initialization
3 Sending data
2 statistics
2 optimizing
1 freeing items
[k-isobe@PMJ41 ~]$

両者に差があるのは、待機状態(Sleep)なセッションがある為です。

■質問■

Q1.
 'FULLTEXT initialization' という状態が出るのは、
 どういう状態でしょうか?
 どうも、groongaを待っているように見えます。

Q2.
 CPU的には余力があるように見えるので、
 接続するクライアントを1.5倍に増やしてみたのですが、
 CPUの使用率はさほど上がらず、
 'FULLTEXT initialization' の行が増えただけでした。
 どうも、groongaの待ち行列が増えただけのように見えます。

 パラメータチューニング等で、更に高速化する方法は無いでしょうか。

 一応、innodb_read_io_threads=8とは設定してありますが
 mroongaには、特にオンメモリ状態では効果は無いと考えています。

TAIYAKU_DATA2.dump.gz - 再現確認用ダミーデータ (24.6 MB) Kentoku SHIBA, 09/24/2013 03:59 am

History

#1 Updated by Kentoku SHIBA almost 5 years ago

いつもお世話になっております。

ひょっとして、同じDBマシン上に
 別のDBを作成し、同じ構造のデータを持たせる
という事をすると
 それぞれのDB毎に対応するgroongaが立ち上がる
のでDB/groongaの個数分速くなる
とかになったりしませんか。

勿論、クライアント毎に、どのDBに接続するかを
バランスさせないといけませんが・・・

mroongaはファイルセットをDB単位で持つので、ひょっとして・・・
と今思いました。

MyISAMなら単にファイルをコピーすれば良いので、すぐ試せるのですが
そうではないので、見込みがあると判るまで試すのは控えます。

クライアント側も修正しないといけなかったりと
結構作業が大変そうなので。

メモリ容量的には7倍にまでDBを複製可能なので
7倍速くなったら物凄く嬉しいです。

※現在、DBマシンとして2台用意し倍速体制で動かしています

#2 Updated by Kentoku SHIBA almost 5 years ago

斯波です。

> Q1.
>  'FULLTEXT initialization' という状態が出るのは、
>  どういう状態でしょうか?
>  どうも、groongaを待っているように見えます。

MySQL的には'FULLTEXT initialization'のフェーズなのですが、
mroonga内部ではこのフェーズで全文検索を実行しています。
このため、「どうも、groongaを待っているように見えます。」と
いうのは正しく、processlistにこの状態が多数見つかるのも
正しいと思われます。

> Q2.
>  CPU的には余力があるように見えるので、
>  接続するクライアントを1.5倍に増やしてみたのですが、
>  CPUの使用率はさほど上がらず、
>  'FULLTEXT initialization' の行が増えただけでした。
>  どうも、groongaの待ち行列が増えただけのように見えます。
>
>  パラメータチューニング等で、更に高速化する方法は無いでしょうか。

こちらを確認するために、テーブル定義、サンプルデータ、サンプルSQL、
MySQLのコンフィグファイルなどを頂くことはできますでしょうか?

どうぞ、ご確認をよろしくお願い致します。

#3 Updated by Kentoku SHIBA almost 5 years ago

いつもお世話になっております。

Q1の回答、ありがとうございました。

Q2に関しましては、肝心のDDLとデータを開示できないので
本質的な部分のみのDDLを開示します。

元のCSVテーブル

CREATE TABLE `TAIYAKU_DATA` (
`id` int(11) NOT NULL ,
`EN_TEXT` text NOT NULL,
`JA_TEXT` text NOT NULL,
) ENGINE=CSV DEFAULT CHARSET=utf8;


mroonga化SQL

alter table TAIYAKU_DATA
modify column id int(11) NOT NULL AUTO_INCREMENT,
add PRIMARY KEY (id),
add FULLTEXT KEY EN_TEXT (EN_TEXT),
add FULLTEXT KEY JA_TEXT (JA_TEXT),
ENGINE=mroonga DEFAULT CHARSET=utf8;

問い合わせ用SQL

"select count(ID) as counts from TAIYAKU_DATA where match(JA_TEXT)
against ('\"" + searchText + "\"' in boolean mode)"
"select count(ID) as counts from TAIYAKU_DATA where match(EN_TEXT)
against ('\"" + searchText + "\"' in boolean mode)"


my.cnfは下記を使用しています。(※32GBメモリマシン用です)

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[client]
port = 3306
socket = /tmp/mysql.sock
default-character-set = utf8
[mysqld]
symbolic-links=1
mroonga_database_path_prefix = "mysql/mroonga.data/"
mroonga_match_escalation_threshold = -1
mroonga_log_level = "ERROR"
skip-name-resolve
innodb_file_per_table
innodb_log_buffer_size = 100M
innodb_buffer_pool_size = 24G

port = 3306
socket = /tmp/mysql.sock
datadir = /var/lib/mysql
key_buffer = 2048M
max_allowed_packet = 160M
table_cache = 5120
table_open_cache = 5120
sort_buffer_size = 20M
read_buffer_size = 20M
read_rnd_buffer_size = 800M
myisam_sort_buffer_size = 1024M
thread_cache_size = 800
query_cache_size = 160M
max_connections = 500
thread_concurrency = 16
innodb_flush_method=O_DIRECT
max_heap_table_size = 5G
[mysqldump]
quick
max_allowed_packet = 16M
default-character-set = utf8
[mysql]
no-auto-rehash
default-character-set = utf8
[isamchk]
key_buffer = 1280M
sort_buffer_size = 1280M
read_buffer = 200M
write_buffer = 200M
[myisamchk]
key_buffer = 1280M
sort_buffer_size = 1280M
read_buffer = 200M
write_buffer = 200M
[mysqlhotcopy]
interactive-timeout
lo-error=/var/log/mysqld.log

#4 Updated by Kentoku SHIBA almost 5 years ago

  • % Done changed from 0 to 10

こちらで再現させたところ、SYSTEM負荷が非常に高い状態になった。 oprofileで確認したところ、以下のような結果になった。

samples  %        image name               app name                 symbol name
1272163  42.4511  vmlinux                  vmlinux                  clear_page_c
478791   15.9769  vmlinux                  vmlinux                  native_safe_halt
37322     1.2454  vmlinux                  vmlinux                  find_vma
35902     1.1980  libc-2.12.so             libc-2.12.so             __memset_x86_64
34608     1.1548  vmlinux                  vmlinux                  split_huge_page
30627     1.0220  vmlinux                  vmlinux                  get_page_from_freelist
26101     0.8710  vmlinux                  vmlinux                  clockevents_notify
25303     0.8443  vmlinux                  vmlinux                  __mem_cgroup_uncharge_common
23434     0.7820  vmlinux                  vmlinux                  schedule
22379     0.7468  vmlinux                  vmlinux                  lookup_page_cgroup
22357     0.7460  vmlinux                  vmlinux                  free_pcppages_bulk
19089     0.6370  vmlinux                  vmlinux                  unmap_vmas
17286     0.5768  libc-2.12.so             libc-2.12.so             __GI_memset
17083     0.5700  vmlinux                  vmlinux                  ktime_get
16212     0.5410  vmlinux                  vmlinux                  lapic_timer_setup
14404     0.4807  vmlinux                  vmlinux                  list_del
14403     0.4806  vmlinux                  vmlinux                  page_remove_rmap
13978     0.4664  vmlinux                  vmlinux                  free_hot_cold_page
13898     0.4638  vmlinux                  vmlinux                  release_pages
12924     0.4313  vmlinux                  vmlinux                  reschedule_interrupt
12176     0.4063  vmlinux                  vmlinux                  __bitmap_empty
12001     0.4005  libgroonga.so.0.0.0      libgroonga.so.0.0.0      grn_expr_create
11954     0.3989  vmlinux                  vmlinux                  clear_huge_page
11431     0.3814  vmlinux                  vmlinux                  rwsem_wake
11272     0.3761  vmlinux                  vmlinux                  select_nohz_load_balancer
10914     0.3642  vmlinux                  vmlinux                  rwsem_down_failed_common
10439     0.3483  vmlinux                  vmlinux                  thread_return
9877      0.3296  vmlinux                  vmlinux                  __list_add
9865      0.3292  vmlinux                  vmlinux                  smp_invalidate_interrupt
9828      0.3280  vmlinux                  vmlinux                  mem_cgroup_split_hugepage_commit
9475      0.3162  vmlinux                  vmlinux                  flush_tlb_others_ipi
9348      0.3119  libc-2.12.so             libc-2.12.so             _int_malloc
9296      0.3102  vmlinux                  vmlinux                  notifier_call_chain
9200      0.3070  vmlinux                  vmlinux                  get_pageblock_flags_group
9185      0.3065  vmlinux                  vmlinux                  page_fault
9154      0.3055  vmlinux                  vmlinux                  select_task_rq_fair
8790      0.2933  vmlinux                  vmlinux                  mem_cgroup_del_lru_list
8525      0.2845  oprofiled                oprofiled                /usr/bin/oprofiled
8344      0.2784  vmlinux                  vmlinux                  __switch_to
8176      0.2728  vmlinux                  vmlinux                  sched_clock
8128      0.2712  vmlinux                  vmlinux                  try_to_wake_up
7225      0.2411  vmlinux                  vmlinux                  __inc_zone_state
7163      0.2390  vmlinux                  vmlinux                  scheduler_ipi
7010      0.2339  vmlinux                  vmlinux                  lru_add_page_tail
6742      0.2250  vmlinux                  vmlinux                  resched_task
6732      0.2246  vmlinux                  vmlinux                  __mod_zone_page_state
6553      0.2187  vmlinux                  vmlinux                  mem_cgroup_get_reclaim_stat_from_page
6525      0.2177  vmlinux                  vmlinux                  tick_broadcast_oneshot_control
6306      0.2104  vmlinux                  vmlinux                  __free_pages_ok
6090      0.2032  vmlinux                  vmlinux                  tick_notify
5839      0.1948  vmlinux                  vmlinux                  __alloc_pages_nodemask
5733      0.1913  vmlinux                  vmlinux                  mem_cgroup_add_lru_list
5658      0.1888  libc-2.12.so             libc-2.12.so             _int_free
5509      0.1838  vmlinux                  vmlinux                  rb_get_reader_page
5488      0.1831  libgroonga.so.0.0.0      libgroonga.so.0.0.0      grn_hash_add
5392      0.1799  vmlinux                  vmlinux                  pick_next_task_fair
5382      0.1796  vmlinux                  vmlinux                  task_rq_lock
5106      0.1704  vmlinux                  vmlinux                  dequeue_entity
5001      0.1669  vmlinux                  vmlinux                  native_apic_mem_write
4989      0.1665  vmlinux                  vmlinux                  enqueue_entity
4884      0.1630  vmlinux                  vmlinux                  read_tsc
4856      0.1620  vmlinux                  vmlinux                  update_page_reclaim_stat
4805      0.1603  vmlinux                  vmlinux                  alloc_pages_vma
4779      0.1595  vmlinux                  vmlinux                  tick_nohz_stop_sched_tick
4771      0.1592  vmlinux                  vmlinux                  enqueue_task
4599      0.1535  vmlinux                  vmlinux                  default_idle
4500      0.1502  vmlinux                  vmlinux                  native_read_tsc
4331      0.1445  oprofile                 oprofile                 /oprofile
4242      0.1416  vmlinux                  vmlinux                  do_IRQ
4196      0.1400  vmlinux                  vmlinux                  update_curr
4100      0.1368  vmlinux                  vmlinux                  rb_erase
4069      0.1358  vmlinux                  vmlinux                  native_apic_mem_read
4040      0.1348  vmlinux                  vmlinux                  clockevents_set_mode
3974      0.1326  vmlinux                  vmlinux                  __mem_cgroup_commit_charge
3931      0.1312  vmlinux                  vmlinux                  c1e_idle
3788      0.1264  vmlinux                  vmlinux                  _cond_resched
3650      0.1218  libgroonga.so.0.0.0      libgroonga.so.0.0.0      grn_io_segment_alloc
3584      0.1196  vmlinux                  vmlinux                  handle_pte_fault
3520      0.1175  vmlinux                  vmlinux                  handle_mm_fault
3457      0.1154  vmlinux                  vmlinux                  __hrtimer_start_range_ns
3268      0.1091  vmlinux                  vmlinux                  rcu_irq_enter
3198      0.1067  vmlinux                  vmlinux                  __do_page_fault
3194      0.1066  vmlinux                  vmlinux                  arch_get_unmapped_area_topdown
3177      0.1060  vmlinux                  vmlinux                  tick_check_oneshot_broadcast
3099      0.1034  vmlinux                  vmlinux                  leave_mm
3088      0.1030  vmlinux                  vmlinux                  rcu_enter_nohz
3073      0.1025  vmlinux                  vmlinux                  __perf_event_task_sched_out
3018      0.1007  vmlinux                  vmlinux                  ____pagevec_lru_add

#5 Updated by Kentoku SHIBA almost 5 years ago

コールグラフ

  samples  %        image name               app name                 symbol name


1995982 46.8789 vmlinux vmlinux clear_page_c 1995982 100.000 vmlinux vmlinux clear_page_c [self]


509449 11.9652 vmlinux vmlinux native_safe_halt 509449 100.000 vmlinux vmlinux native_safe_halt [self]


57862 1.3590 libc-2.12.so libc-2.12.so __memset_x86_64 57862 100.000 libc-2.12.so libc-2.12.so __memset_x86_64 [self]


54617 1.2828 vmlinux vmlinux split_huge_page 54617 100.000 vmlinux vmlinux split_huge_page [self]


51489 1.2093 vmlinux vmlinux find_vma 51489 100.000 vmlinux vmlinux find_vma [self]


46021 1.0809 vmlinux vmlinux get_page_from_freelist 46021 100.000 vmlinux vmlinux get_page_from_freelist [self]


#6 Updated by Kentoku SHIBA almost 5 years ago

  • Assignee changed from Kentoku SHIBA to Kouhei Sutou

お手数ではございますが、一度こちらの現象のご確認をお願いします。

#7 Updated by Kentoku SHIBA over 4 years ago

データなどを変更して「FULLTEXT initialization」が多く出力できるパターンを再現した。

再現手順 MySQL 5.5系を利用してください。 添付のdumpファイルで、テーブルとデータを作成し、 以下のコマンドで、ストアドプロシージャを 複数のターミナルでMySQLにログインし実行してください。

mysql> CALL P_SEL_TAIYAKU_DATA3();
再現した際のoprofile -lの結果
samples  %        image name               app name                 symbol name
407608   29.6405  vmlinux                  vmlinux                  ioremap_page_range
242244   17.6156  vmlinux                  vmlinux                  hpet_msi_mask
122974    8.9425  vmlinux                  vmlinux                  vmtruncate_range
56307     4.0945  libgroonga.so.0.0.0      libgroonga.so.0.0.0      /usr/lib64/libgroonga.so.0.0.0
18678     1.3582  vmlinux                  vmlinux                  clocksource_watchdog
13978     1.0165  libc-2.12.so             libc-2.12.so             __memset_x86_64
10447     0.7597  vmlinux                  vmlinux                  pci_scan_bridge
9276      0.6745  vmlinux                  vmlinux                  arch_get_unmapped_area_topdown
8445      0.6141  vmlinux                  vmlinux                  mem_cgroup_print_oom_info
8443      0.6140  vmlinux                  vmlinux                  lookup_swap_cgroup

#8 Updated by Kouhei Sutou over 4 years ago

以下のようにMySQL 5.5.33で試した。groonga/mroongaはmasterである。

MySQLのインストール:

mysql-5.5.33% BUILD/compile-amd64-max
mysql-5.5.33% sudo mkdir -p /usr/local/mysql
mysql-5.5.33% sudo chown -R $(id --user --name):$(id --group --name) /usr/local/mysql
mysql-5.5.33% make install

mroongaのインストール:

mroonga% ./autogen.sh
mroonga% ./configure --with-mysql-source=$PWD/../mysql-5.5.33 --with-mysql-config=$PWD/../mysql-5.5.33/scripts/mysql_config
mroonga% make
mroonga% make install

MySQLのセットアップ

% cd /usr/local/mysql
% scripts/mysql_install_db
% bin/mysqld --gdb

データベース構築

% /usr/local/mysql/bin/mysql -u root mysql < .../mroonga/data/install.sql
% /usr/local/mysql/bin/mysql -u root mysql -e 'create database mroonga_1802;'
% /usr/local/mysql/bin/mysql -u root mroonga_1802 < TAIYAKU_DATA2.dump

試験

% /usr/local/mysql/bin/mysql -u root mroonga_1802 -e 'CALL P_SEL_TAIYAKU_DATA3();' &
% /usr/local/mysql/bin/mysql -u root mroonga_1802 -e 'CALL P_SEL_TAIYAKU_DATA3();' &
% /usr/local/mysql/bin/mysql -u root mroonga_1802 -e 'CALL P_SEL_TAIYAKU_DATA3();' &
% ...

topでみたCPU使用率が↑で起動したプロセス数 * 100より小さければ再現している。これを、できるだけ起動したプロセス数 * 100に近づけられるとよい。

#9 Updated by Kouhei Sutou over 4 years ago

CPUを使い切れないのはロックで待っているからじゃないの?と予想して調べることにした。

gdbでバックトレースを確認したところ、検索結果を格納する一時テーブルを作成するところでlockしていた。

https://github.com/groonga/groonga/blob/master/lib/db.c#L877

で、これはなんと私が入れたやつ https://github.com/groonga/groonga/commit/1f1a77402e22a75ca74d488694cd584ac8566dc6 https://github.com/groonga/groonga/commit/c7db6bf753b4f8e25757e2447e82469d7b4cf2cc で、 https://gist.github.com/y-ken/9a5d564d37a58e810abe のSEGVを直すためらしい。で、実際に直った。 twitter.com/yoshi_ken/status/347232929472196610

今みると、その直前にコミットしている https://github.com/groonga/groonga/commit/27f5e4b6bfa0d5e8bc869600a86ee439edb951a3 でio.cのレベルでロックするようにしているのでdb.cの方はいらないような気がした。少なくとも一時テーブルのときはいらなそう。

後でgroongaレベルで再現ケースを作ってみて、db.cのやつがなくてもいいなら抜こう。

で、とりあえず、db.cのロックをなくしたやつを試してみたけど、CPU使用率はあがらない。他にもあるのかも。

#10 Updated by Kouhei Sutou over 4 years ago

CPUコア数(4つ)と同じ数(4つ)だけmysqlを立ちあげたら350%くらいCPUを使っていた。 1つ増やすと250%になって、もうひとつ増やすと190%になった。

同時に処理する検索処理数がCPUコア数以上になると遅くなるってだけかも。とすると、これはMySQLのせいな気がする。

#11 Updated by Kouhei Sutou over 4 years ago

  • Assignee changed from Kouhei Sutou to Kentoku SHIBA
  • % Done changed from 10 to 80

MySQLのソースをちら見してみると、1接続1スレッドというモデルのようなので、クライアント側でコア数以上接続数を張らないみたいにしないといけなそう。

インターネットで探してみると、MySQLのエンタープライズ版とMariaDBはスレッドプールを提供しているようだ。それらを使う場合はスレッドプールで使うスレッド数をコア数と同じにすれば常によいパフォーマンスを出せると考えられる。

MariaDBでスレッドプールを使って接続をさばくにはmy.cnfに thread_handling=pool-of-threads と書けば良さそう。 https://mariadb.com/kb/en/thread-pool-in-mariadb-55/

というのが私が調べて得られた情報です。これで回答できそうでしょうか!? しばさんに担当を戻します。

#12 Updated by Kentoku SHIBA over 4 years ago

  • Assignee changed from Kentoku SHIBA to Kouhei Sutou

MariaDB 10.0系で、スレッドプールを試そうと環境を構築してみたが、
こちらの環境(CentOS 6.3 6コア)では、スレッドプールなしで試して
せいぜい160%程度までしかCPUが利用されない。
./sync.shで持ってきたソースを、compile-amd64-maxでビルドしてみたが、
同じく160%程度しかCPUが利用されない。

お手数ですが、すとうさんの環境では、MariaDB 10.0系を利用した場合、
CPU使用率がどのようになるかご確認頂けませんでしょうか?

#13 Updated by Kouhei Sutou over 4 years ago

わかりました!

ちなみに、160%程度までCPUを使い切れないときはクライアント数はいくつにしていましたか?コア数(6)より多いかどうかが気になりました。というのも、私が実験した時( http://redmine.groonga.org/issues/1802#note-10 )は以下のようにクライアント数をコア数より多くするとCPUを使い切れなかったからです。

CPUコア数(4つ)と同じ数(4つ)だけmysqlを立ちあげたら350%くらいCPUを使っていた。 1つ増やすと250%になって、もうひとつ増やすと190%になった。

Also available in: Atom PDF