Bug #2335

並列度をあげると性能が悪化する

Added by Kouhei Sutou almost 4 years ago. Updated almost 4 years ago.

Status:担当者作業中Start date:02/15/2014
Priority:NormalDue date:
Assignee:Kenji Maruyama% Done:

0%

Category:-
Target version:-

Description

次のような報告をもらいました。

進め方は次の通りです。

  • 現象を確認する。
    • → 再現しなかった
      • 追加情報の提供をお願いする。
    • → 再現した。
      • 原因がMySQL、Mroonga、Groongaのどれかを切り分ける。切り分ける順番は下のレイヤーから。つまり、Groonga→Mroonga→MySQL。理由は下のレイヤーですでに遅いならそれより上でなにをやってもダメなのでムダな作業を減らせるから。
  • Groongaが問題かを切り分ける方法: Groongaで同等のクエリーを同じ並列度で実行して再現するか確認。
    • → 再現する。
      • Groongaが問題。相談。
    • → 再現しない。
      • Groongaは問題ではない。
  • Mroongaが問題かを切り分ける方法: MyISAMまたはInnoDBで同じクエリーを実行して再現するか確認。
    • → 再現する。
      • Mroongaは問題ではない。MySQLが問題。
    • → 再現しない。
      • Mroongaの問題。相談。

https://gist.github.com/kazeburo/9014939

mroongaでクエリを投げる並列数をあげていくと、レスポンスが悪化する件


使用しているデータは http://blog.livedoor.jp/staff/ の記事データです。1500件ほどあります


環境は EC2 cc2.8xlarge 8コア 32コア


MySQL 5.6.15。オラクル公式MySQL rpmを使用
mroonga 4.0
groonga 4.0

mroongaのビルドは http://blog.nomadscafe.jp/2013/12/vagrantprovisionermroongarpm---mysql-casual-advent-calendar-2013.html この方法でビルドしたもの


セットアップ手順


wget http://nomadscafe.jp/mroonga/mroonga-rpm.tar
wget http://nomadscafe.jp/mroonga/my.cnf
wget http://nomadscafe.jp/mroonga/bench.pl
wget http://nomadscafe.jp/mroonga/blog30.sql
tar xf mroonga-rpm.tar
rpm -Uvh mroonga-rpm/MySQL-shared-compat*.rpm
cp my.cnf /etc/my.cnf
rpm -Uvh mroonga-rpm/MySQL-client-5*.rpm mroonga-rpm/MySQL-devel-5*.rpm \
mroonga-rpm/MySQL-server-5*.rpm mroonga-rpm/MySQL-shared-5*.rpm
/etc/init.d/mysql start
export MYSQL_PWD=$(tail -2 /root/.mysql_secret | awk -F ': ' '{print $2}')
mysqladmin -uroot password ""
export MYSQL_PWD=""
mysql -uroot -e 'update user SET Password="" where User="root"' mysql
rpm -Uvh mroonga-rpm/groonga*.rpm mroonga-rpm/mecab*.rpm mroonga-rpm/mysql56-mroonga*.rpm
yum -y install perl-DBD-mysql perl-Time-HiRes
mysqladmin create article_index
cat blog30.sql | mysql article_index

ベンチマーク実行


perl bench.pl 並列数

最後にかかった時間がでます


結果


# perl bench.pl 1
done: 11.0142660140991
# perl bench.pl 2
done: 14.6641170978546
# perl bench.pl 3
done: 12.7114961147308
# perl bench.pl 4
done: 13.4998869895935
# perl bench.pl 5
done: 17.3568599224091
# perl bench.pl 6
done: 22.2315490245819
# perl bench.pl 7
done: 30.3295059204102
# perl bench.pl 8
done: 43.5253119468689
# perl bench.pl 16
done: 126.63294506073

並列数3~4を超えると線形に悪くなっていく

callgrind.out.3073 (1.93 MB) Kenji Maruyama, 03/03/2014 03:24 pm

callgrind_1.png (161 KB) Kenji Maruyama, 03/03/2014 03:39 pm

callgrind_2.png (149 KB) Kenji Maruyama, 03/03/2014 03:39 pm

callgrind_3.png (125 KB) Kenji Maruyama, 03/03/2014 03:49 pm

callgrind.out.23660 (1.79 MB) Kenji Maruyama, 03/03/2014 09:17 pm

callgrind_5.png (109 KB) Kenji Maruyama, 03/03/2014 09:20 pm

callgrind_4.png (131 KB) Kenji Maruyama, 03/03/2014 09:20 pm

lock_count.png (165 KB) Kenji Maruyama, 03/05/2014 01:36 pm

cond_push.png (133 KB) Kenji Maruyama, 03/05/2014 01:36 pm

store_field.png (192 KB) Kenji Maruyama, 03/05/2014 01:36 pm

inno_slow.trace (4.49 MB) Kenji Maruyama, 03/05/2014 02:48 pm

inno.trace (4.09 MB) Kenji Maruyama, 03/05/2014 02:48 pm

mrn.trace (5.94 MB) Kenji Maruyama, 03/05/2014 02:49 pm

mrn_slow.trace (6.49 MB) Kenji Maruyama, 03/05/2014 02:49 pm

user_time.png (170 KB) Kenji Maruyama, 03/05/2014 03:58 pm

scan_time.png (139 KB) Kenji Maruyama, 03/05/2014 03:58 pm

History

#1 Updated by Kenji Maruyama almost 4 years ago

  • Assignee set to Kenji Maruyama

#2 Updated by Kenji Maruyama almost 4 years ago

  • Status changed from 新規 to 担当者作業中

環境166上virtulabox + vagrantで作成

  • 環境

仮想環境 166上, OS: CentOS6.3 final, 仮想メモリ 8GB, 仮想CPU数 8

  • セットアップ手順

上記と同一

  • 結果 : 下記
perl bench.pl 1
done: 10.0112698078156
perl bench.pl 2
done: 17.4635438919067
perl bench.pl 3
done: 31.4171600341797
perl bench.pl 4
done: 46.6850171089172
perl bench.pl 5
done: 65.9751129150391
perl bench.pl 6
done: 87.1144981384277
perl bench.pl 7
done: 111.279965877533
perl bench.pl 8
done: 131.255181074142

環境だけ作成しておくつもりでしたが、計測もしてしまいました。接続するクライアントのプロセス数を増やすと、レスポンスタイムが報告以上にかかっていることが結果からわかります。(3回ほど計測しましたが、ほぼ結果同じです)

#3 Updated by Kouhei Sutou almost 4 years ago

おぉ!

では、Groongaが問題かどうかを切り分けて欲しいです!

Groongaが問題かを切り分ける方法: Groongaで同等のクエリーを同じ並列度で実行して再現するか確認。

#4 Updated by Kenji Maruyama almost 4 years ago

Groongaが問題かどうかを切り分けて欲しいです!

了解です。他のタスクと並行して切り分けもやってみます。

#5 Updated by Kouhei Sutou almost 4 years ago

了解です。他のタスクと並行して切り分けもやってみます。

ありがとうございます!

並行すると作業効率が落ちそうなら、こっちは他のタスクが終わった後でいいです!

#6 Updated by Kenji Maruyama almost 4 years ago

並行すると作業効率が落ちそうなら、こっちは他のタスクが終わった後でいいです!

ありがとうございます。了解です。

#7 Updated by Kenji Maruyama almost 4 years ago

groongaに原因あるかどうかデータの切り出しより先にすぐできるmyisam, innodb の計測をしてみました。

同じスキーマ、それぞれ2回実行、以下結果になります。

myisamも並列度をあげると、同じようなレスポンス悪化が見られます。innodbはほぼ変化なしです。

myisam

perl bench.pl 1
done: 22.9963250160217
perl bench.pl 2
done: 31.3915781974792
perl bench.pl 3
done: 36.5774919986725
perl bench.pl 4
done: 46.7998051643372
perl bench.pl 5
done: 58.1001341342926
perl bench.pl 6
done: 80.5998611450195
perl bench.pl 7
done: 100.056504964828
perl bench.pl 8
done: 125.477907180786

innodb

perl bench.pl 1
done: 9.1737539768219
perl bench.pl 2
done: 10.2431261539459
perl bench.pl 3
done: 11.2294509410858
perl bench.pl 4
done: 11.6730780601501
perl bench.pl 5
done: 13.0327279567719
perl bench.pl 6
done: 13.7880651950836
perl bench.pl 7
done: 15.429514169693
perl bench.pl 8
done: 17.0099129676819

#8 Updated by Kenji Maruyama almost 4 years ago

groongaに原因あるかどうかデータの切り出しより先にすぐできる

実行SQLをtraceしてみたら、bench.plで実行しているsql は以下のSQLの繰り返しでした。

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id FROM article_index_0099 WHERE blog_id=30 AND status=1 AND MATCH(public_terms) AGAINST(CONCAT_
WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE) ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

なるべく近いgroongaコマンドに書き換えて

select --table article_index_0099 --filter 'blog_id==30 && status==1' --match_columns public_terms
 --query "livedoor ブログ blog 開発" --limit 10 --offset 0 --sortby -regist_datetime --output_columns article_id

上記をgrn.commandとして、同じperl計測スクリプトに入れて計測

#!/usr/bin/perl

use Time::HiRes;
use List::Util qw/shuffle/;
$|=1;

my $p = $ARGV[0] || 1;

my @data;
for (1..1000) {
    push @data, "livedoor ブログ blog 開発";
}
my $t2 = Time::HiRes::time;
for (1..$p) {
    fork and next;
    srand();
    for my $l ( shuffle @data ) {
        my $t = Time::HiRes::time;
        `groonga /var/lib/mysql/article_index.mrn < grn.command`;
        my $e = Time::HiRes::time - $t;
    }
    exit;
}

while ( waitpid( -1, 0) >= 0 ) {};
my $e2 = Time::HiRes::time - $t2;
print "done: $e2\n";

結果

perl bench_grn.pl 1
done: 23.9495630264282
perl bench_grn.pl 2
done: 22.9562938213348
perl bench_grn.pl 3
done: 21.0725040435791
perl bench_grn.pl 4
done: 19.368793964386
perl bench_grn.pl 5
done: 18.6346600055695
perl bench_grn.pl 6
done: 18.0511858463287
perl bench_grn.pl 7
done: 18.4227521419525
perl bench_grn.pl 8
done: 18.3796830177307

groonga command によるマルチプロセスな呼び出し方にすると、プロセス数を増やしてもレスポンスが悪化するということはなさそうです。

  • まとめ

innodbは悪化しないので、mroongaも悪化しないようにできるはず

groonga commandによる呼び出しは悪化しない。

myisamは悪化する。

innodbは悪化しない。

mroongaは悪化する。

#9 Updated by Kenji Maruyama almost 4 years ago

#7, #8

そういえば、myisam, innodbにinsertしたデータは日本語で、前処理のNgramかmecab等で分かち書きし忘れてました。全文検索できていないはずなので、Ngram処理を施して#7の計測をやり直します。

#10 Updated by Kouhei Sutou almost 4 years ago

Transparent HugePagesを切ると少し改善するとのことです!

https://gist.github.com/kazeburo/9014939/#comment-1174035

Enable Transparent Huge Pages


# echo 'always' > /sys/kernel/mm/transparent_hugepage/enabled
# perl bench.pl 1
done: 11.2478802204132
# perl bench.pl 2
done: 12.5930590629578
# perl bench.pl 3
done: 9.81607699394226
# perl bench.pl 4
done: 13.3511309623718
# perl bench.pl 5
done: 17.5803909301758
# perl bench.pl 6
done: 22.4946398735046
# perl bench.pl 7
done: 29.6415500640869
# perl bench.pl 8
done: 42.2584500312805

Disable Transparent Huge Pages


# echo 'never' > /sys/kernel/mm/transparent_hugepage/enabled
# perl bench.pl 1
done: 8.79889822006226
# perl bench.pl 2
done: 12.0252130031586
# perl bench.pl 3
done: 13.0487220287323
# perl bench.pl 4
done: 9.82021903991699
# perl bench.pl 5
done: 11.6668729782104
# perl bench.pl 6
done: 14.4229891300201
# perl bench.pl 7
done: 17.8033969402313
# perl bench.pl 8
done: 22.2788860797882
# perl bench.pl 16
done: 100.067826032639

#11 Updated by Kouhei Sutou almost 4 years ago

Kenji Maruyama wrote:

#2335, #2335


そういえば、myisam, innodbにinsertしたデータは日本語で、前処理のNgramかmecab等で分かち書きし忘れてました。全文検索できていないはずなので、Ngram処理を施して #2335 の計測をやり直します。

あ、そこは頑張らなくてよいと思います! livedoorとかblogとかアルファベットの検索後も入っているので傾向はかわらないと思います。

Groongaが問題ではないということがわかったので、MySQLかストレージエンジン周りが問題だといえます。

ということで、デバッグビルドしたMySQLでも再現するか試してもらえますか?デバッグビルドでも再現するなら情報をいろいろ取れるので調査をだいぶしやすくなります。試すのはMroongaだけでいいです!OSもDebianでよいです!

#12 Updated by Kenji Maruyama almost 4 years ago

あ、そこは頑張らなくてよいと思います! livedoorとかblogとかアルファベットの検索後も入っているので傾向はかわらないと思います。ということで、デバッグビルドしたMySQLでも再現するか試してもらえますか?デバッグビルドでも再現するなら情報をいろいろ取れるので調査をだいぶしやすくなります。試すのはMroongaだけでいいです!OSもDebianでよいです!

了解です。

#13 Updated by Kenji Maruyama almost 4 years ago

手元のVM CentOS6.4, Mroongaデバッグビルド環境 (仮想CPU数1, 仮想メモリ192MB 2GB)

Mroongaを同じスクリプトで実行すると以下のように再現できています。

perl bench.pl 1
done: 13.8890850543976
perl bench.pl 2
done: 27.5693762302399
perl bench.pl 3
done: 40.6767818927765
perl bench.pl 4
done: 54.5005331039429
perl bench.pl 5
done: 67.5723669528961
perl bench.pl 6
done: 82.7577788829803
perl bench.pl 7
done: 93.5334331989288
perl bench.pl 8
done: 114.323168992996

#14 Updated by Kouhei Sutou almost 4 years ago

1CPUだと、マルチプロセスにしても性能があがらないのはそうだろうなぁという気がするので、再現しているというには弱い気がしました。。。

#15 Updated by Kenji Maruyama almost 4 years ago

1CPUだと、マルチプロセスにしても性能があがらないのはそうだろうなぁという気がするので、再現しているというには弱い気がしました。。。

なるほど。ホストの環境がCore i7(コア数2)なので、VMの仮想コア数も2にしてみました。仮想メモリは変わりません(2GB)

結果は以下です。あまり変わらないです。プロセス数を増やすとCPU使用率は190%キープしたまま、166の仮想コア8の場合は "perl bench.pl 8" にしてもCPU使用率400%以下ですね。

問題を提起してくださった方もXen上だから、仮想環境だけの問題とかってありえるのか気になるところです。

perl bench.pl 1
done: 16.0867178440094
perl bench.pl 2
done: 25.9294331073761
perl bench.pl 3
done: 40.9422659873962
perl bench.pl 4
done: 56.724347114563
perl bench.pl 5
done: 68.0438520908356
perl bench.pl 6
done: 79.8139672279358
perl bench.pl 7
done: 91.7395260334015
perl bench.pl 8
done: 101.526599884033

#16 Updated by Kenji Maruyama almost 4 years ago

仮想環境だけの問題とかってありえるのか気になるところです。

コア数が少ない環境だと再現できているかわからないので、Mroongaデバッグビルド環境を166, 仮想環境でないDebian7上で作って再現できるか試してみます。

#17 Updated by Kenji Maruyama almost 4 years ago

仮想環境だけの問題とかってありえるのか気になるところです。

仮想環境でない166上(コア数16)Mroongaでやってみました。結果は以下です。

残念ながら悪化しています。

念のためGroonga直で仮想でない環境でどうなるかやってみます。

perl bench.pl 1
done: 15.7196090221405
perl bench.pl 2
done: 31.1072499752045
perl bench.pl 3
done: 50.9436268806458
perl bench.pl 4
done: 74.0121719837189
perl bench.pl 5
done: 92.7166209220886
perl bench.pl 6
done: 109.53476190567
perl bench.pl 7
done: 124.748542070389
perl bench.pl 8
done: 139.602772951126

#18 Updated by Kenji Maruyama almost 4 years ago

念のためGroonga直で仮想でない環境でどうなるかやってみます。

以下により仮想環境も問題ないが、仮想環境でない所でも問題ありません。

perl bench_grn.pl 1
done: 10.8900661468506
perl bench_grn.pl 2
done: 17.0855040550232
perl bench_grn.pl 3
done: 12.0771791934967
perl bench_grn.pl 4
done: 8.72521805763245
perl bench_grn.pl 5
done: 8.3594388961792
perl bench_grn.pl 6
done: 7.31337904930115
perl bench_grn.pl 7
done: 7.84156489372253
perl bench_grn.pl 8
done: 7.35583591461182

#19 Updated by Kenji Maruyama almost 4 years ago

"perl bench_grn.pl 1" で 1000回, "perl bench_grn.pl 8"で8000回 selectコマンドが走るようになっています。毎回のselect文は同じで、以下になります。

root@localhost mysql>SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id FROM article_index_0099 WHERE blog_id=30 AND status=1 AND MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE) ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

myisam , innodb , mroonga の検索結果同じです。以下になります。

+------------+
| article_id |
+------------+
|   51840937 |
|   51840729 |
|   51839804 |
|   51839409 |
|   51839731 |
|   51839146 |
|   51838462 |
|   51838259 |
|   51838145 |
|   51834586 |
+------------+
10 rows in set (0.03 sec)

#20 Updated by Kenji Maruyama almost 4 years ago

それぞれのストレージエンジンのSELECT COUNT(*) の結果

root@localhost mysql>SELECT COUNT(*) FROM article_index_0099 WHERE blog_id=30 AND status=1 AND MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE) ORDER BY regist_datetime DESC;
innodb
+----------+
| COUNT(*) |
+----------+
|     1209 |
+----------+
1 row in set (0.01 sec)

myisam
+----------+
| COUNT(*) |
+----------+
|     1208 |
+----------+
1 row in set (0.03 sec)

mroonga
+----------+
| COUNT(*) |
+----------+
|     1449 |
+----------+
1 row in set (0.01 sec)

#21 Updated by Kenji Maruyama almost 4 years ago

groonga コマンドでマルチプロセス接続で計測しましたが、クエリキャッシュオフ、スレッド数制限は設けませんでした。仮想環境上にて groonga GQTP serverを使って、クエリキャッシュオフ、スレッド数設定して再計測しました。

/var/lib/mysql/article_index.mrn にあるデータサイズは前回同様 1505件.

手順

  • sync
  • echo 3 > /proc/sys/vm/drop_caches
  • GQTP server起動
sudo groonga -d /var/lib/mysql/article_index.mrn  -t 1 --cache-limit 0 (1はスレッド数、bench_grn_gqtp.pl のプロセス数に合わせて設定)
  • 計測, スクリプトは以下
perl bench_grn_gqtp.pl 1 (1はプロセス数、適宜変更)


bench_grn_gqtp.pl: 

!/usr/bin/perl

use Time::HiRes;
use List::Util qw/shuffle/;
$|=1;

my $p = $ARGV[0] || 1;

my @data;
for (1..1000) {
    push @data, "livedoor ブログ blog 開発";
}
my $t2 = Time::HiRes::time;
for (1..$p) {
    fork and next;
    srand();
    for my $l ( shuffle @data ) {
        # $l =~ s!([\(\)~\+><\-*])!\\$1!g;
        my $t = Time::HiRes::time;
        `groonga -c < grn.command`;
        my $e = Time::HiRes::time - $t;
        # print "[$$] slow $e\n" if $e > 3;
    }
    exit;
}

while ( waitpid( -1, 0) >= 0 ) {};
my $e2 = Time::HiRes::time - $t2;
print "done: $e2\n";


grn.command:

select --table article_index_0099 --filter 'blog_id==30 && status==1' --match_columns public_terms --query "livedoor ブログ blog 開発" --limit 10 --offset 0 --sortby -regist_datetime --output_columns article_id --cache-limit 0

結果

http://redmine.groonga.org/issues/2335#note-8 とあまり変わらない結果となった。

スレッド数
1 19.6925809383392
2 19.8210418224335
3 14.5688169002533
4 12.8144898414612
5 11.3152451515198
6 11.7725739479065
7 17.43385887146
8 19.2289009094238

#22 Updated by Kenji Maruyama almost 4 years ago

  • ロードアベレージ比較

8プロセス同時検索 (perl bench.pl 8)

Mroonga

[vagrant@localhost mrn_concurrent]$ sar -q 1 100
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/03/2014  _x86_64_    (8 CPU)

03:44:30 AM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15
03:44:31 AM         3       300      1.23      1.76      0.90
03:44:32 AM         1       300      1.23      1.76      0.90
03:44:33 AM         3       300      1.77      1.87      0.94
03:44:34 AM         3       300      1.77      1.87      0.94
03:44:35 AM         4       300      1.77      1.87      0.94
03:44:36 AM         6       300      1.77      1.87      0.94
03:44:37 AM         6       300      1.77      1.87      0.94
03:44:38 AM         2       300      2.27      1.97      0.98
03:44:39 AM         1       300      2.27      1.97      0.98
03:44:40 AM         1       300      2.27      1.97      0.98
03:44:41 AM         9       300      2.27      1.97      0.98
03:44:42 AM         4       300      2.27      1.97      0.98
03:44:43 AM         4       300      2.81      2.08      1.02
03:44:44 AM         5       300      2.81      2.08      1.02
03:44:45 AM         1       300      2.81      2.08      1.02
03:44:46 AM         3       300      2.81      2.08      1.02
03:44:47 AM         2       300      2.81      2.08      1.02
03:44:48 AM         3       300      3.14      2.17      1.05
03:44:49 AM         6       300      3.14      2.17      1.05
03:44:50 AM         4       300      3.14      2.17      1.05
03:44:51 AM         1       300      3.14      2.17      1.05
03:44:52 AM         1       300      3.14      2.17      1.05
03:44:53 AM         3       300      3.53      2.26      1.09
03:44:54 AM         8       300      3.53      2.26      1.09
03:44:55 AM         3       300      3.53      2.26      1.09
03:44:56 AM         8       300      3.53      2.26      1.09
03:44:57 AM         3       300      3.53      2.26      1.09
03:44:58 AM         2       300      3.89      2.36      1.13
03:44:59 AM         1       300      3.89      2.36      1.13
03:45:00 AM         5       300      3.89      2.36      1.13
03:45:01 AM         4       300      3.89      2.36      1.13
03:45:02 AM         1       300      3.89      2.36      1.13
03:45:03 AM         4       300      3.98      2.40      1.15
03:45:04 AM         7       300      3.98      2.40      1.15
03:45:05 AM         3       300      3.98      2.40      1.15
03:45:06 AM         4       300      3.98      2.40      1.15
03:45:07 AM         1       300      3.98      2.40      1.15
03:45:08 AM         8       300      4.30      2.49      1.18
03:45:09 AM         2       300      4.30      2.49      1.18
03:45:10 AM         1       300      4.30      2.49      1.18
03:45:11 AM         5       300      4.30      2.49      1.18
03:45:12 AM         8       300      4.30      2.49      1.18
03:45:13 AM         1       300      4.52      2.57      1.21

03:45:13 AM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15
03:45:14 AM         4       300      4.52      2.57      1.21
03:45:15 AM         5       300      4.52      2.57      1.21
03:45:16 AM         2       300      4.52      2.57      1.21
03:45:17 AM         2       300      4.52      2.57      1.21
03:45:18 AM         8       300      4.71      2.64      1.24
03:45:19 AM         7       300      4.71      2.64      1.24
03:45:20 AM         8       300      4.71      2.64      1.24
03:45:21 AM         3       300      4.71      2.64      1.24
03:45:22 AM         2       300      4.71      2.64      1.24
03:45:23 AM         2       300      4.90      2.71      1.28
03:45:24 AM         6       300      4.90      2.71      1.28
03:45:25 AM         5       300      4.90      2.71      1.28
03:45:26 AM         8       300      4.90      2.71      1.28
03:45:27 AM         6       300      4.90      2.71      1.28
03:45:28 AM         1       300      4.74      2.72      1.28
03:45:29 AM         5       300      4.74      2.72      1.28
03:45:30 AM         5       300      4.74      2.72      1.28
03:45:31 AM         2       300      4.74      2.72      1.28
03:45:32 AM         8       300      4.74      2.72      1.28
03:45:33 AM         5       300      4.44      2.69      1.28
03:45:34 AM         3       300      4.44      2.69      1.28
03:45:35 AM         5       300      4.44      2.69      1.28
03:45:36 AM         3       300      4.44      2.69      1.28
03:45:37 AM         7       300      4.44      2.69      1.28
03:45:38 AM         2       300      4.17      2.66      1.28
03:45:39 AM         2       300      4.17      2.66      1.28
03:45:40 AM         3       300      4.17      2.66      1.28
03:45:41 AM         5       300      4.17      2.66      1.28
03:45:42 AM         2       300      4.17      2.66      1.28
03:45:43 AM         3       300      4.47      2.75      1.32
03:45:44 AM         2       300      4.47      2.75      1.32
03:45:45 AM         5       300      4.47      2.75      1.32
03:45:46 AM         1       300      4.47      2.75      1.32
03:45:47 AM         9       300      4.47      2.75      1.32
03:45:48 AM         4       300      4.44      2.77      1.33
03:45:49 AM         2       300      4.44      2.77      1.33
03:45:50 AM         3       300      4.44      2.77      1.33
03:45:51 AM         8       300      4.44      2.77      1.33
03:45:52 AM         3       300      4.44      2.77      1.33
03:45:53 AM         2       300      4.72      2.86      1.37
03:45:54 AM         2       300      4.72      2.86      1.37
03:45:55 AM         2       300      4.72      2.86      1.37
03:45:56 AM         2       300      4.72      2.86      1.37

03:45:56 AM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15
03:45:57 AM         2       300      4.72      2.86      1.37
03:45:58 AM         2       300      4.90      2.93      1.40
03:45:59 AM         3       300      4.90      2.93      1.40
03:46:00 AM         6       300      4.90      2.93      1.40
03:46:01 AM         2       300      4.90      2.93      1.40
03:46:02 AM         3       300      4.90      2.93      1.40
03:46:03 AM         5       300      5.15      3.01      1.43
03:46:04 AM         2       300      5.15      3.01      1.43
03:46:05 AM         4       300      5.15      3.01      1.43
03:46:06 AM         4       300      5.15      3.01      1.43
03:46:07 AM         5       300      5.15      3.01      1.43
03:46:08 AM         2       300      4.90      2.99      1.43
03:46:09 AM         3       300      4.90      2.99      1.43
03:46:10 AM         3       300      4.90      2.99      1.43
Average:            4       300      4.01      2.52      1.21

比較 innodb

[vagrant@localhost mrn_concurrent]$ sar -q 1 15
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/03/2014  _x86_64_    (8 CPU)

03:48:10 AM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15
03:48:11 AM         9       300      1.75      2.73      1.55
03:48:12 AM         8       300      1.75      2.73      1.55
03:48:13 AM         8       300      1.61      2.69      1.54
03:48:14 AM         8       300      1.61      2.69      1.54
03:48:15 AM         6       300      1.61      2.69      1.54
03:48:16 AM         8       300      1.61      2.69      1.54
03:48:17 AM         9       300      1.61      2.69      1.54
03:48:18 AM         9       300      1.64      2.67      1.54
03:48:19 AM         8       300      1.64      2.67      1.54
03:48:20 AM         9       300      1.64      2.67      1.54
03:48:21 AM         6       300      1.64      2.67      1.54
03:48:22 AM         8       300      1.64      2.67      1.54
03:48:23 AM         8       300      1.59      2.65      1.54
03:48:24 AM         8       300      1.59      2.65      1.54
03:48:25 AM         1       300      1.59      2.65      1.54
Average:            8       300      1.63      2.68      1.54
  • ldavg-1 ロードアベレージ(1分間の平均値)をみると、MroongaがInnoDBの2倍以上になっている。runq-sz(実行待ちプロセス数) は逆に InnoDBがMroongaの2倍になっている。

#23 Updated by Kenji Maruyama almost 4 years ago

CPU負荷(CPUのコア数ごとの使用率)とI/O負荷

8プロセス同時検索 (perl bench.pl 8)

  • Mroonga
inux 2.6.32-279.el6.x86_64 (localhost.localdomain)  03/03/2014  _x86_64_    (8 CPU)

04:16:06 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:07 AM     all     22.90      0.00     14.36      0.00      0.00     62.74
04:16:07 AM       0     25.00      0.00     22.73      0.00      0.00     52.27
04:16:07 AM       1     34.44      0.00     18.89      0.00      0.00     46.67
04:16:07 AM       2     24.18      0.00     17.58      0.00      0.00     58.24
04:16:07 AM       3     29.67      0.00     14.29      0.00      0.00     56.04
04:16:07 AM       4     15.96      0.00     11.70      0.00      0.00     72.34
04:16:07 AM       5     18.09      0.00      9.57      0.00      0.00     72.34
04:16:07 AM       6     15.05      0.00      9.68      0.00      0.00     75.27
04:16:07 AM       7     20.00      0.00     12.63      0.00      0.00     67.37

04:16:07 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:08 AM     all     21.08      0.00     13.78      0.00      0.00     65.14
04:16:08 AM       0     24.72      0.00     20.22      0.00      0.00     55.06
04:16:08 AM       1     25.27      0.00     19.78      0.00      0.00     54.95
04:16:08 AM       2     27.78      0.00     17.78      0.00      0.00     54.44
04:16:08 AM       3     25.81      0.00     13.98      0.00      0.00     60.22
04:16:08 AM       4     23.66      0.00     10.75      0.00      0.00     65.59
04:16:08 AM       5     15.05      0.00     11.83      0.00      0.00     73.12
04:16:08 AM       6     12.63      0.00      9.47      0.00      0.00     77.89
04:16:08 AM       7     14.74      0.00      6.32      0.00      0.00     78.95

04:16:08 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:09 AM     all     20.79      0.00     14.77      0.00      0.00     64.43
04:16:09 AM       0     27.47      0.00     23.08      0.00      0.00     49.45
04:16:09 AM       1     25.00      0.00     25.00      0.00      0.00     50.00
04:16:09 AM       2     25.84      0.00     14.61      0.00      0.00     59.55
04:16:09 AM       3     25.84      0.00     15.73      0.00      0.00     58.43
04:16:09 AM       4     18.09      0.00     12.77      0.00      0.00     69.15
04:16:09 AM       5     13.19      0.00      9.89      0.00      0.00     76.92
04:16:09 AM       6     18.48      0.00     11.96      0.00      0.00     69.57
04:16:09 AM       7     12.50      0.00      6.25      0.00      0.00     81.25

04:16:09 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:10 AM     all     17.36      0.00     13.19      1.21      0.00     68.24
04:16:10 AM       0     17.98      0.00     22.47      0.00      0.00     59.55
04:16:10 AM       1     18.68      0.00     20.88      0.00      0.00     60.44
04:16:10 AM       2     26.37      0.00     16.48      8.79      0.00     48.35
04:16:10 AM       3     20.88      0.00     12.09      0.00      0.00     67.03
04:16:10 AM       4     16.13      0.00     10.75      0.00      0.00     73.12
04:16:10 AM       5     20.00      0.00     11.58      0.00      0.00     68.42
04:16:10 AM       6     15.79      0.00      8.42      0.00      0.00     75.79
04:16:10 AM       7      6.12      0.00      3.06      0.00      0.00     90.82

04:16:10 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:11 AM     all     18.16      0.00     12.74      0.00      0.00     69.11
04:16:11 AM       0     29.21      0.00     17.98      0.00      0.00     52.81
04:16:11 AM       1     27.47      0.00     18.68      0.00      0.00     53.85
04:16:11 AM       2     20.22      0.00     17.98      0.00      0.00     61.80
04:16:11 AM       3     15.05      0.00     16.13      0.00      0.00     68.82
04:16:11 AM       4     15.22      0.00     11.96      0.00      0.00     72.83
04:16:11 AM       5     16.30      0.00      8.70      0.00      0.00     75.00
04:16:11 AM       6     12.77      0.00      6.38      0.00      0.00     80.85
04:16:11 AM       7      8.25      0.00      4.12      0.00      0.00     87.63

04:16:11 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:12 AM     all     19.89      0.00     15.40      0.00      0.00     64.71
04:16:12 AM       0     27.47      0.00     24.18      0.00      0.00     48.35
04:16:12 AM       1     24.72      0.00     22.47      0.00      0.00     52.81
04:16:12 AM       2     22.22      0.00     18.89      0.00      0.00     58.89
04:16:12 AM       3     19.10      0.00     16.85      0.00      0.00     64.04
04:16:12 AM       4     14.89      0.00     13.83      0.00      0.00     71.28
04:16:12 AM       5     21.05      0.00     10.53      0.00      0.00     68.42
04:16:12 AM       6     12.63      0.00      8.42      0.00      0.00     78.95
04:16:12 AM       7     19.15      0.00     10.64      0.00      0.00     70.21

04:16:12 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:13 AM     all     25.85      0.00     15.32      0.00      0.00     58.82
04:16:13 AM       0     41.11      0.00     20.00      0.00      0.00     38.89
04:16:13 AM       1     22.22      0.00     24.44      0.00      0.00     53.33
04:16:13 AM       2     28.89      0.00     17.78      0.00      0.00     53.33
04:16:13 AM       3     25.00      0.00     16.30      0.00      0.00     58.70
04:16:13 AM       4     24.18      0.00     12.09      0.00      0.00     63.74
04:16:13 AM       5     22.83      0.00     13.04      0.00      0.00     64.13
04:16:13 AM       6     21.51      0.00      8.60      0.00      0.00     69.89
04:16:13 AM       7     20.65      0.00     10.87      0.00      0.00     68.48

04:16:14 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:16:15 AM     all     18.11      0.00     13.38      0.00      0.00     68.51
04:16:15 AM       0     24.72      0.00     20.22      0.00      0.00     55.06
04:16:15 AM       1     24.44      0.00     22.22      0.00      0.00     53.33
04:16:15 AM       2     20.65      0.00     17.39      0.00      0.00     61.96
04:16:15 AM       3     14.29      0.00     19.78      0.00      0.00     65.93
04:16:15 AM       4     19.15      0.00      9.57      0.00      0.00     71.28
04:16:15 AM       5     12.63      0.00      7.37      0.00      0.00     80.00
04:16:15 AM       6     13.83      0.00      8.51      0.00      0.00     77.66
04:16:15 AM       7     13.40      0.00      4.12      0.00      0.00     82.47

... 省略

04:17:45 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:17:46 AM     all     21.24      0.00     12.99      0.00      0.00     65.76
04:17:46 AM       0     33.33      0.00     18.89      0.00      0.00     47.78
04:17:46 AM       1     32.61      0.00     17.39      0.00      0.00     50.00
04:17:46 AM       2     26.37      0.00     17.58      0.00      0.00     56.04
04:17:46 AM       3     16.30      0.00     19.57      0.00      0.00     64.13
04:17:46 AM       4     22.83      0.00     13.04      0.00      0.00     64.13
04:17:46 AM       5     17.20      0.00     10.75      0.00      0.00     72.04
04:17:46 AM       6     18.95      0.00      5.26      0.00      0.00     75.79
04:17:46 AM       7      5.15      0.00      4.12      0.00      0.00     90.72

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all     20.17      0.00     13.61      0.22      0.00     66.00
Average:          0     27.60      0.00     20.53      0.38      0.00     51.49
Average:          1     27.04      0.00     20.57      0.27      0.00     52.13
Average:          2     23.36      0.00     17.26      0.53      0.00     58.84
Average:          3     22.37      0.00     15.51      0.38      0.00     61.74
Average:          4     19.40      0.00     12.29      0.24      0.00     68.08
Average:          5     17.02      0.00     10.21      0.00      0.00     72.77
Average:          6     14.62      0.00      7.97      0.00      0.00     77.41
Average:          7     10.92      0.00      5.52      0.00      0.00     83.57

InnoDB

[vagrant@localhost mrn_concurrent]$ sar -P ALL 1 10
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/03/2014  _x86_64_    (8 CPU)

04:20:59 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:00 AM     all     88.48      0.00      5.12      0.00      0.00      6.40
04:21:00 AM       0     90.38      0.00      3.85      0.00      0.00      5.77
04:21:00 AM       1     89.32      0.00      3.88      0.00      0.00      6.80
04:21:00 AM       2     88.89      0.00      5.05      0.00      0.00      6.06
04:21:00 AM       3     87.63      0.00      6.19      0.00      0.00      6.19
04:21:00 AM       4     90.53      0.00      3.16      0.00      0.00      6.32
04:21:00 AM       5     87.23      0.00      6.38      0.00      0.00      6.38
04:21:00 AM       6     86.17      0.00      6.38      0.00      0.00      7.45
04:21:00 AM       7     87.10      0.00      5.38      0.00      0.00      7.53

04:21:00 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:01 AM     all     89.53      0.00      4.91      0.00      0.00      5.56
04:21:01 AM       0     90.29      0.00      3.88      0.00      0.00      5.83
04:21:01 AM       1     90.29      0.00      3.88      0.00      0.00      5.83
04:21:01 AM       2     90.00      0.00      4.00      0.00      0.00      6.00
04:21:01 AM       3     89.47      0.00      5.26      0.00      0.00      5.26
04:21:01 AM       4     90.43      0.00      4.26      0.00      0.00      5.32
04:21:01 AM       5     88.30      0.00      5.32      0.00      0.00      6.38
04:21:01 AM       6     90.22      0.00      5.43      0.00      0.00      4.35
04:21:01 AM       7     88.04      0.00      7.61      0.00      0.00      4.35

04:21:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:02 AM     all     89.49      0.00      5.00      0.00      0.00      5.51
04:21:02 AM       0     89.32      0.00      4.85      0.00      0.00      5.83
04:21:02 AM       1     89.22      0.00      4.90      0.00      0.00      5.88
04:21:02 AM       2     92.93      0.00      3.03      0.00      0.00      4.04
04:21:02 AM       3     91.75      0.00      3.09      0.00      0.00      5.15
04:21:02 AM       4     87.37      0.00      7.37      0.00      0.00      5.26
04:21:02 AM       5     87.63      0.00      5.15      0.00      0.00      7.22
04:21:02 AM       6     90.43      0.00      4.26      0.00      0.00      5.32
04:21:02 AM       7     85.26      0.00      8.42      0.00      0.00      6.32

04:21:02 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:03 AM     all     90.12      0.00      4.75      0.00      0.00      5.13
04:21:03 AM       0     91.26      0.00      3.88      0.00      0.00      4.85
04:21:03 AM       1     92.16      0.00      2.94      0.00      0.00      4.90
04:21:03 AM       2     91.00      0.00      4.00      0.00      0.00      5.00
04:21:03 AM       3     89.80      0.00      5.10      0.00      0.00      5.10
04:21:03 AM       4     90.62      0.00      4.17      0.00      0.00      5.21
04:21:03 AM       5     89.13      0.00      5.43      0.00      0.00      5.43
04:21:03 AM       6     89.36      0.00      5.32      0.00      0.00      5.32
04:21:03 AM       7     87.37      0.00      7.37      0.00      0.00      5.26

04:21:03 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:04 AM     all     90.04      0.00      4.98      0.00      0.00      4.98
04:21:04 AM       0     90.29      0.00      3.88      0.00      0.00      5.83
04:21:04 AM       1     92.00      0.00      3.00      0.00      0.00      5.00
04:21:04 AM       2     91.09      0.00      4.95      0.00      0.00      3.96
04:21:04 AM       3     90.72      0.00      5.15      0.00      0.00      4.12
04:21:04 AM       4     88.54      0.00      6.25      0.00      0.00      5.21
04:21:04 AM       5     91.40      0.00      4.30      0.00      0.00      4.30
04:21:04 AM       6     90.43      0.00      5.32      0.00      0.00      4.26
04:21:04 AM       7     90.22      0.00      4.35      0.00      0.00      5.43

04:21:04 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:05 AM     all     90.13      0.00      4.74      0.00      0.00      5.13
04:21:05 AM       0     89.42      0.00      4.81      0.00      0.00      5.77
04:21:05 AM       1     90.29      0.00      4.85      0.00      0.00      4.85
04:21:05 AM       2     92.00      0.00      4.00      0.00      0.00      4.00
04:21:05 AM       3     89.80      0.00      5.10      0.00      0.00      5.10
04:21:05 AM       4     90.53      0.00      4.21      0.00      0.00      5.26
04:21:05 AM       5     85.26      0.00      8.42      0.00      0.00      6.32
04:21:05 AM       6     91.58      0.00      3.16      0.00      0.00      5.26
04:21:05 AM       7     88.30      0.00      6.38      0.00      0.00      5.32

04:21:05 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:06 AM     all     90.00      0.00      4.36      0.00      0.00      5.64
04:21:06 AM       0     89.52      0.00      4.76      0.00      0.00      5.71
04:21:06 AM       1     91.18      0.00      2.94      0.00      0.00      5.88
04:21:06 AM       2     93.00      0.00      3.00      0.00      0.00      4.00
04:21:06 AM       3     88.66      0.00      4.12      0.00      0.00      7.22
04:21:06 AM       4     89.58      0.00      5.21      0.00      0.00      5.21
04:21:06 AM       5     89.13      0.00      5.43      0.00      0.00      5.43
04:21:06 AM       6     88.54      0.00      5.21      0.00      0.00      6.25
04:21:06 AM       7     89.36      0.00      5.32      0.00      0.00      5.32

04:21:06 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:07 AM     all     90.13      0.00      4.49      0.00      0.00      5.38
04:21:07 AM       0     90.29      0.00      3.88      0.00      0.00      5.83
04:21:07 AM       1     91.18      0.00      3.92      0.00      0.00      4.90
04:21:07 AM       2     92.93      0.00      3.03      0.00      0.00      4.04
04:21:07 AM       3     90.62      0.00      4.17      0.00      0.00      5.21
04:21:07 AM       4     88.42      0.00      5.26      0.00      0.00      6.32
04:21:07 AM       5     91.67      0.00      3.12      0.00      0.00      5.21
04:21:07 AM       6     88.30      0.00      5.32      0.00      0.00      6.38
04:21:07 AM       7     88.17      0.00      5.38      0.00      0.00      6.45

04:21:07 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:08 AM     all     89.64      0.00      4.73      0.00      0.00      5.63
04:21:08 AM       0     91.35      0.00      2.88      0.00      0.00      5.77
04:21:08 AM       1     91.09      0.00      3.96      0.00      0.00      4.95
04:21:08 AM       2     89.11      0.00      4.95      0.00      0.00      5.94
04:21:08 AM       3     89.69      0.00      4.12      0.00      0.00      6.19
04:21:08 AM       4     88.66      0.00      5.15      0.00      0.00      6.19
04:21:08 AM       5     89.58      0.00      5.21      0.00      0.00      5.21
04:21:08 AM       6     87.10      0.00      7.53      0.00      0.00      5.38
04:21:08 AM       7     89.36      0.00      5.32      0.00      0.00      5.32

04:21:08 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:21:09 AM     all     89.53      0.00      4.39      0.00      0.00      6.07
04:21:09 AM       0     91.35      0.00      2.88      0.00      0.00      5.77
04:21:09 AM       1     90.20      0.00      3.92      0.00      0.00      5.88
04:21:09 AM       2     88.78      0.00      4.08      0.00      0.00      7.14
04:21:09 AM       3     89.80      0.00      5.10      0.00      0.00      5.10
04:21:09 AM       4     90.32      0.00      4.30      0.00      0.00      5.38
04:21:09 AM       5     88.30      0.00      5.32      0.00      0.00      6.38
04:21:09 AM       6     87.10      0.00      5.38      0.00      0.00      7.53
04:21:09 AM       7     88.30      0.00      5.32      0.00      0.00      6.38

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all     89.71      0.00      4.75      0.00      0.00      5.54
Average:          0     90.35      0.00      3.96      0.00      0.00      5.69
Average:          1     90.69      0.00      3.82      0.00      0.00      5.49
Average:          2     90.97      0.00      4.01      0.00      0.00      5.02
Average:          3     89.79      0.00      4.74      0.00      0.00      5.46
Average:          4     89.50      0.00      4.94      0.00      0.00      5.57
Average:          5     88.76      0.00      5.41      0.00      0.00      5.83
Average:          6     88.92      0.00      5.32      0.00      0.00      5.75
Average:          7     88.14      0.00      6.09      0.00      0.00      5.77
  • MroongaがInnoDBと比較して%userが極端に低く、%systemが高く、%iowaitが少し発生していることが見られる。

#24 Updated by Kenji Maruyama almost 4 years ago

メモリ使用率

8プロセス同時検索 (perl bench.pl 8)

Mroonga

[vagrant@localhost mrn_concurrent]$ sar -rW 1 100
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/03/2014  _x86_64_    (8 CPU)

03:59:29 AM  pswpin/s pswpout/s
03:59:30 AM      0.00      0.00

03:59:29 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
03:59:30 AM   6805392   1155552     14.52     26116    629584   1871484     18.67

03:59:30 AM  pswpin/s pswpout/s
03:59:31 AM      0.00      0.00

03:59:30 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
03:59:31 AM   6807544   1153400     14.49     26124    629720   1863176     18.58

03:59:31 AM  pswpin/s pswpout/s
03:59:32 AM      0.00      0.00

03:59:31 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
03:59:32 AM   6796860   1164084     14.62     26124    629880   1916360     19.12

03:59:32 AM  pswpin/s pswpout/s
03:59:33 AM      0.00      0.00

03:59:32 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
03:59:33 AM   6793136   1167808     14.67     26124    630004   1887612     18.83

... 省略

04:01:06 AM  pswpin/s pswpout/s
04:01:07 AM      0.00      0.00

04:01:06 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:01:07 AM   6771756   1189188     14.94     26276    642116   1916372     19.12

04:01:07 AM  pswpin/s pswpout/s
04:01:08 AM      0.00      0.00

04:01:07 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:01:08 AM   6779872   1181072     14.84     26276    642288   1891900     18.87

04:01:08 AM  pswpin/s pswpout/s
04:01:09 AM      0.00      0.00

04:01:08 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:01:09 AM   6767192   1193752     15.00     26276    642432   1932872     19.28

04:01:09 AM  pswpin/s pswpout/s
04:01:10 AM      0.00      0.00

04:01:09 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:01:10 AM   6784072   1176872     14.78     26276    642576   1904328     19.00

Average:     pswpin/s pswpout/s
Average:         0.00      0.00

Average:    kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
Average:      6788059   1172885     14.73     26198    636061   1897703     18.93

InnoDB

[vagrant@localhost mrn_concurrent]$ sar -rW 1 15
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/03/2014  _x86_64_    (8 CPU)

04:27:15 AM  pswpin/s pswpout/s
04:27:16 AM      0.00      0.00

04:27:15 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:16 AM   6801300   1159644     14.57     28568    710460   1640500     16.36

04:27:16 AM  pswpin/s pswpout/s
04:27:17 AM      0.00      0.00

04:27:16 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:17 AM   6800184   1160760     14.58     28576    711528   1640500     16.36

04:27:17 AM  pswpin/s pswpout/s
04:27:18 AM      0.00      0.00

04:27:17 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:18 AM   6798820   1162124     14.60     28584    712596   1640500     16.36

04:27:18 AM  pswpin/s pswpout/s
04:27:19 AM      0.00      0.00

04:27:18 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:19 AM   6798076   1162868     14.61     28592    713628   1640500     16.36

04:27:19 AM  pswpin/s pswpout/s
04:27:20 AM      0.00      0.00

04:27:19 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:20 AM   6796712   1164232     14.62     28600    714672   1640500     16.36

04:27:20 AM  pswpin/s pswpout/s
04:27:21 AM      0.00      0.00

04:27:20 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:21 AM   6795720   1165224     14.64     28608    715712   1640500     16.36

04:27:21 AM  pswpin/s pswpout/s
04:27:22 AM      0.00      0.00

04:27:21 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:22 AM   6794604   1166340     14.65     28616    716768   1640500     16.36

04:27:22 AM  pswpin/s pswpout/s
04:27:23 AM      0.00      0.00

04:27:22 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:23 AM   6793612   1167332     14.66     28624    717796   1640500     16.36

04:27:23 AM  pswpin/s pswpout/s
04:27:24 AM      0.00      0.00

04:27:23 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:24 AM   6792620   1168324     14.68     28632    718832   1640500     16.36

04:27:24 AM  pswpin/s pswpout/s
04:27:25 AM      0.00      0.00

04:27:24 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:25 AM   6791628   1169316     14.69     28640    719884   1640500     16.36

04:27:25 AM  pswpin/s pswpout/s
04:27:26 AM      0.00      0.00

04:27:25 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:26 AM   6790512   1170432     14.70     28648    720932   1640500     16.36

04:27:26 AM  pswpin/s pswpout/s
04:27:27 AM      0.00      0.00

04:27:26 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:27 AM   6789148   1171796     14.72     28656    721944   1640500     16.36

04:27:27 AM  pswpin/s pswpout/s
04:27:28 AM      0.00      0.00

04:27:27 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:28 AM   6788156   1172788     14.73     28664    722948   1640500     16.36

04:27:28 AM  pswpin/s pswpout/s
04:27:29 AM      0.00      0.00

04:27:28 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:29 AM   6787536   1173408     14.74     28672    723924   1640500     16.36

04:27:29 AM  pswpin/s pswpout/s
04:27:30 AM      0.00      0.00

04:27:29 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
04:27:30 AM   6786296   1174648     14.76     28680    724984   1640500     16.36

Average:     pswpin/s pswpout/s
Average:         0.00      0.00

Average:    kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit
Average:      6793662   1167282     14.66     28624    717774   1640500     16.36

  • メモリ使用率MroongaとInnoDBとでそれほど差異がみられない。

#25 Updated by Kenji Maruyama almost 4 years ago

OProfileを使ってCPUごとのプロファイリング

8プロセス同時検索 (perl bench.pl 8)

手順

sudo opcontrol --no-vmlinux
sudo opcontrol --start
perl bench.pl 8
sudo opcontrol --stop
sudo opcontrol --dump

Mroonga

opreport -l -m cpu /usr/lib64/mysql/plugin/ha_mroonga.so.0.0.0

Profiling through timer interrupt
Processes with a thread ID of 14021
Processes with a thread ID of 14174
Processes with a thread ID of 14175
Processes with a thread ID of 14176
Processes with a thread ID of 14177
Processes with a thread ID of 14178
Processes with a thread ID of 14179
Processes with a thread ID of 14180
samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        symbol name
23024    67.7894  23028    68.1161  23093    68.5435  23748    68.7451  23495    68.4148  23585    68.4238  23449    68.6125  23456    68.7960  mrn_storage_ft_get_relevance
4221     12.4279  4147     12.2667  3988     11.8370  4194     12.1407  4108     11.9620  4202     12.1907  4055     11.8651  4062     11.9138  ha_mroonga::storage_store_fields(unsigned cha
r*, unsigned int)
954       2.8089  963       2.8485  934       2.7723  907       2.6256  926       2.6964  895       2.5965  937       2.7417  987       2.8949  ha_mroonga::storage_store_field_integer(Field
*, char const*, unsigned int)
717       2.1111  650       1.9227  681       2.0213  670       1.9395  651       1.8956  712       2.0656  672       1.9663  676       1.9827  ha_mroonga::storage_store_field_datetime2(Fie
ld*, char const*, unsigned int)
645       1.8991  624       1.8458  663       1.9679  597       1.7282  642       1.8694  607       1.7610  625       1.8288  614       1.8009  ha_mroonga::storage_ft_read(unsigned char*)
611       1.7990  599       1.7718  528       1.5672  628       1.8179  566       1.6481  642       1.8625  564       1.6503  507       1.4870  ha_mroonga::storage_store_field_blob(Field*,
char const*, unsigned int)
609       1.7931  584       1.7275  629       1.8670  619       1.7919  695       2.0238  627       1.8190  629       1.8405  611       1.7921  ha_mroonga::storage_store_field(Field*, char
const*, unsigned int)
431       1.2690  437       1.2926  446       1.3238  444       1.2853  407       1.1851  428       1.2417  407       1.1909  445       1.3052  mrn::encoding::set(_grn_ctx*, charset_info_st
 const*)
346       1.0187  387       1.1447  346       1.0270  361       1.0450  405       1.1793  361       1.0473  361       1.0563  427       1.2524  ha_mroonga::position(unsigned char const*)
331       0.9746  309       0.9140  367       1.0893  355       1.0276  349       1.0162  351       1.0183  374       1.0943  320       0.9386  mrn::TimeConverter::TimeConverter()
303       0.8921  325       0.9613  314       0.9320  320       0.9263  333       0.9697  326       0.9458  343       1.0036  344       1.0089  mrn_change_encoding
285       0.8391  281       0.8312  312       0.9261  261       0.7555  294       0.8561  286       0.8297  260       0.7608  261       0.7655  mrn::DebugColumnAccess::DebugColumnAccess(TAB
LE*, st_bitmap*)
262       0.7714  268       0.7927  239       0.7094  282       0.8163  252       0.7338  236       0.6847  271       0.7930  260       0.7626  mrn::TimeConverter::grn_time_to_mysql_time(lo
ng long, st_mysql_time*)
240       0.7066  196       0.5798  198       0.5877  168       0.4863  207       0.6028  219       0.6354  206       0.6028  227       0.6658  ha_mroonga::storage_position(unsigned char co
nst*)
231       0.6801  264       0.7809  187       0.5550  273       0.7903  280       0.8153  298       0.8645  266       0.7783  211       0.6189  ha_mroonga::ft_read(unsigned char*)
225       0.6625  182       0.5384  225       0.6678  202       0.5847  228       0.6639  216       0.6267  222       0.6496  187       0.5485  mrn::DebugColumnAccess::~DebugColumnAccess()
115       0.3386  117       0.3461  93        0.2760  113       0.3271  97        0.2825  79        0.2292  118       0.3453  106       0.3109  mrn::TimeConverter::~TimeConverter()
109       0.3209  127       0.3757  122       0.3621  109       0.3155  87        0.2533  101       0.2930  114       0.3336  91        0.2669  ha_mroonga::storage_read_time(unsigned int, u
nsigned int, unsigned long long)
60        0.1767  73        0.2159  61        0.1811  53        0.1534  57        0.1660  49        0.1422  52        0.1522  61        0.1789  ha_mroonga::storage_records_in_range(unsigned in
t, st_key_range*, st_key_range*)
58        0.1708  52        0.1538  66        0.1959  55        0.1592  86        0.2504  58        0.1683  79        0.2312  53        0.1554  ha_mroonga::storage_scan_time()
31        0.0913  18        0.0532  32        0.0950  32        0.0926  20        0.0582  19        0.0551  17        0.0497  33        0.0968  ha_mroonga::storage_unlock_row()
17        0.0501  16        0.0473  20        0.0594  7         0.0203  10        0.0291  18        0.0522  17        0.0497  10        0.0293  ha_mroonga::unlock_row()
11        0.0324  13        0.0385  10        0.0297  13        0.0376  8         0.0233  13        0.0377  9         0.0263  10        0.0293  ha_mroonga::generic_ft_init_ext_select(unsigned
int, unsigned int, String*)
9         0.0265  4         0.0118  5         0.0148  3         0.0087  5         0.0146  5         0.0145  6         0.0176  1         0.0029  ha_mroonga::storage_info_variable_data_file_leng
th()
6         0.0177  4         0.0118  0              0  3         0.0087  0              0  7         0.0203  1         0.0029  3         0.0088  ha_mroonga::is_enable_optimization()
6         0.0177  2         0.0059  5         0.0148  1         0.0029  4         0.0116  3         0.0087  5         0.0146  3         0.0088  ha_mroonga::table_flags() const
5         0.0147  1         0.0030  4         0.0119  1         0.0029  0              0  4         0.0116  3         0.0088  2         0.0059  mrn_clear_alter_share
4         0.0118  2         0.0059  0              0  2         0.0058  2         0.0058  2         0.0058  4         0.0117  2         0.0059  ha_mroonga::extra(ha_extra_function)
4         0.0118  1         0.0030  2         0.0059  1         0.0029  1         0.0029  0              0  0              0  0              0  ha_mroonga::storage_encode_multiple_column_key(s
t_key*, unsigned char const*, unsigned int, unsigned char*, unsigned int*)
4         0.0118  7         0.0207  4         0.0119  3         0.0087  5         0.0146  3         0.0087  0              0  5         0.0147  mrn::MultipleColumnKeyCodec::encode(unsigned cha
r const*, unsigned int, unsigned char*, unsigned int*)
3         0.0088  3         0.0089  3         0.0089  4         0.0116  5         0.0146  6         0.0174  5         0.0146  4         0.0117  ha_mroonga::check_fast_order_limit(_grn_table_so
rt_key**, int*, long long*)
3         0.0088  1         0.0030  0              0  1         0.0029  0              0  0              0  2         0.0059  0              0  ha_mroonga::clear_empty_value_records()
3         0.0088  4         0.0118  1         0.0030  2         0.0058  1         0.0029  1         0.0029  1         0.0029  1         0.0029  ha_mroonga::generic_ft_init()
3         0.0088  2         0.0059  7         0.0208  3         0.0087  6         0.0175  4         0.0116  5         0.0146  7         0.0205  ha_mroonga::generic_ft_init_ext_prepare_expressi
on_in_boolean_mode(st_mrn_ft_info*, String*, _grn_obj*, _grn_obj*, _grn_obj*, _grn_obj*)
3         0.0088  9         0.0266  4         0.0119  10        0.0289  6         0.0175  6         0.0174  4         0.0117  8         0.0235  ha_mroonga::index_flags(unsigned int, unsigned i
nt, bool) const
3         0.0088  0              0  3         0.0089  0              0  5         0.0146  2         0.0058  5         0.0146  1         0.0029  ha_mroonga::lock_count() const
3         0.0088  3         0.0089  2         0.0059  2         0.0058  1         0.0029  0              0  1         0.0029  3         0.0088  ha_mroonga::primary_key_is_clustered()
3         0.0088  2         0.0059  2         0.0059  2         0.0058  5         0.0146  3         0.0087  5         0.0146  5         0.0147  ha_mroonga::read_time(unsigned int, unsigned int
, unsigned long long)
3         0.0088  1         0.0030  2         0.0059  1         0.0029  2         0.0058  0              0  3         0.0088  7         0.0205  mrn::FieldNormalizer::should_normalize()
3         0.0088  5         0.0148  10        0.0297  1         0.0029  2         0.0058  3         0.0087  4         0.0117  4         0.0117  mrn_is_geo_key
2         0.0059  1         0.0030  3         0.0089  1         0.0029  3         0.0087  2         0.0058  2         0.0059  1         0.0029  ha_mroonga::check_count_skip(unsigned long, unsi
gned long, bool)
2         0.0059  1         0.0030  0              0  3         0.0087  0              0  1         0.0029  1         0.0029  1         0.0029  ha_mroonga::clear_cursor()
2         0.0059  1         0.0030  2         0.0059  2         0.0058  1         0.0029  4         0.0116  1         0.0029  1         0.0029  ha_mroonga::cond_push(Item const*)
2         0.0059  5         0.0148  1         0.0030  0              0  1         0.0029  1         0.0029  1         0.0029  0              0  ha_mroonga::external_lock(THD*, int)
2         0.0059  4         0.0118  3         0.0089  1         0.0029  0              0  2         0.0058  2         0.0059  2         0.0059  ha_mroonga::file_size(char const*)
2         0.0059  3         0.0089  1         0.0030  2         0.0058  1         0.0029  1         0.0029  2         0.0059  5         0.0147  ha_mroonga::ft_init()
2         0.0059  1         0.0030  3         0.0089  1         0.0029  1         0.0029  0              0  1         0.0029  2         0.0059  ha_mroonga::generic_extra(ha_extra_function)
2         0.0059  1         0.0030  0              0  3         0.0087  4         0.0116  3         0.0087  1         0.0029  5         0.0147  ha_mroonga::generic_reset()
2         0.0059  0              0  0              0  0              0  0              0  1         0.0029  0              0  1         0.0029  ha_mroonga::rnd_init(bool)
2         0.0059  4         0.0118  1         0.0030  7         0.0203  4         0.0116  4         0.0116  3         0.0088  4         0.0117  ha_mroonga::storage_index_flags(unsigned int, un
signed int, bool) const
2         0.0059  1         0.0030  3         0.0089  2         0.0058  2         0.0058  0              0  3         0.0088  2         0.0059  ha_mroonga::storage_info(unsigned int)
2         0.0059  1         0.0030  1         0.0030  0              0  3         0.0087  1         0.0029  0              0  1         0.0029  ha_mroonga::storage_lock_count() const
2         0.0059  1         0.0030  4         0.0119  2         0.0058  1         0.0029  0              0  0              0  2         0.0059  ha_mroonga::storage_store_lock(THD*, st_thr_lock
_data**, thr_lock_type)
2         0.0059  1         0.0030  0              0  1         0.0029  2         0.0058  0              0  2         0.0059  0              0  ha_mroonga::storage_table_flags() const
2         0.0059  2         0.0059  1         0.0030  2         0.0058  1         0.0029  1         0.0029  1         0.0029  3         0.0088  mrn::ConditionConverter::is_convertable(Item con
st*)
2         0.0059  2         0.0059  1         0.0030  1         0.0029  0              0  0              0  0              0  0              0  mrn::FieldNormalizer::is_text_type()
2         0.0059  3         0.0089  2         0.0059  5         0.0145  1         0.0029  5         0.0145  0              0  2         0.0059  mrn::MultipleColumnKeyCodec::get_key_info(KEY_PA
RT_INFO*, mrn::MultipleColumnKeyCodec::DataType*, unsigned int*)
2         0.0059  2         0.0059  0              0  1         0.0029  1         0.0029  1         0.0029  0              0  2         0.0059  mrn_generic_ft_clear
2         0.0059  1         0.0030  2         0.0059  0              0  1         0.0029  1         0.0029  1         0.0029  0              0  mrn_get_slot_data
1         0.0029  2         0.0059  0              0  1         0.0029  2         0.0058  1         0.0029  0              0  0              0  ha_mroonga::multi_range_read_info_const(unsigned
 int, st_range_seq_if*, void*, unsigned int, unsigned int*, unsigned int*, Cost_estimate*)
1         0.0029  3         0.0089  2         0.0059  1         0.0029  5         0.0146  3         0.0087  1         0.0029  0              0  ha_mroonga::reset()
1         0.0029  0              0  4         0.0119  2         0.0058  1         0.0029  1         0.0029  0              0  1         0.0029  ha_mroonga::rnd_end()
1         0.0029  0              0  3         0.0089  4         0.0116  4         0.0116  1         0.0029  5         0.0146  1         0.0029  ha_mroonga::scan_time()
1         0.0029  6         0.0177  3         0.0089  4         0.0116  3         0.0087  1         0.0029  2         0.0059  3         0.0088  ha_mroonga::should_normalize(Field*) const
1         0.0029  4         0.0118  1         0.0030  3         0.0087  1         0.0029  0              0  2         0.0059  1         0.0029  ha_mroonga::storage_cond_push(Item const*)
1         0.0029  1         0.0030  2         0.0059  2         0.0058  1         0.0029  1         0.0029  2         0.0059  3         0.0088  ha_mroonga::storage_estimate_rows_upper_bound()
1         0.0029  2         0.0059  0              0  0              0  1         0.0029  1         0.0029  0              0  1         0.0029  ha_mroonga::storage_ft_init_ext(unsigned int, un
signed int, String*)
1         0.0029  1         0.0030  0              0  0              0  1         0.0029  2         0.0058  1         0.0029  0              0  ha_mroonga::storage_multi_range_read_info_const(
unsigned int, st_range_seq_if*, void*, unsigned int, unsigned int*, unsigned int*, Cost_estimate*)
1         0.0029  0              0  0              0  0              0  0              0  0              0  0              0  0              0  ha_mroonga::storage_rebind_psi()
1         0.0029  0              0  0              0  0              0  0              0  0              0  1         0.0029  0              0  ha_mroonga::storage_reset()
1         0.0029  0              0  0              0  2         0.0058  3         0.0087  0              0  1         0.0029  0              0  ha_mroonga::storage_rnd_init(bool)
1         0.0029  2         0.0059  1         0.0030  1         0.0029  0              0  1         0.0029  1         0.0029  2         0.0059  ha_mroonga::storage_rnd_pos(unsigned char*, unsi
gned char*)
1         0.0029  0              0  1         0.0030  0              0  2         0.0058  0              0  1         0.0029  0              0  ha_mroonga::store_lock(THD*, st_thr_lock_data**,
 thr_lock_type)
1         0.0029  0              0  1         0.0030  0              0  1         0.0029  1         0.0029  0              0  0              0  ha_mroonga::unbind_psi()
1         0.0029  0              0  3         0.0089  1         0.0029  3         0.0087  3         0.0087  1         0.0029  0              0  mrn::ConditionConverter::ConditionConverter(_grn
_ctx*, _grn_obj*, bool)
1         0.0029  2         0.0059  1         0.0030  1         0.0029  3         0.0087  4         0.0116  3         0.0088  0              0  mrn::ConditionConverter::is_convertable(Item_fun
c const*)
1         0.0029  0              0  1         0.0030  2         0.0058  2         0.0058  1         0.0029  1         0.0029  0              0  mrn::ConditionConverter::is_convertable_binary_o
peration(Item_field const*, Item*, Item_func::Functype)
1         0.0029  1         0.0030  2         0.0059  2         0.0058  1         0.0029  3         0.0087  1         0.0029  1         0.0029  mrn::ConditionConverter::normalize_field_type(en
um_field_types)
1         0.0029  1         0.0030  0              0  0              0  0              0  5         0.0145  0              0  0              0  mrn::ConditionConverter::~ConditionConverter()
1         0.0029  1         0.0030  1         0.0030  3         0.0087  0              0  0              0  3         0.0088  1         0.0029  mrn::FieldNormalizer::FieldNormalizer(_grn_ctx*,
 THD*, Field*)
1         0.0029  2         0.0059  2         0.0059  3         0.0087  2         0.0058  2         0.0058  0              0  1         0.0029  mrn::MultipleColumnKeyCodec::MultipleColumnKeyCo
dec(_grn_ctx*, THD*, st_key*)
0              0  1         0.0030  0              0  0              0  1         0.0029  0              0  1         0.0029  0              0  ha_mroonga::clear_cursor_geo()
0              0  0              0  1         0.0030  0              0  1         0.0029  0              0  1         0.0029  0              0  ha_mroonga::clear_search_result()
0              0  0              0  2         0.0059  1         0.0029  0              0  0              0  0              0  0              0  ha_mroonga::clear_search_result_geo()
0              0  4         0.0118  1         0.0030  4         0.0116  0              0  3         0.0087  2         0.0059  2         0.0059  ha_mroonga::estimate_rows_upper_bound()
0              0  3         0.0089  1         0.0030  3         0.0087  2         0.0058  1         0.0029  1         0.0029  2         0.0059  ha_mroonga::ft_init_ext(unsigned int, unsigned i
nt, String*)
0              0  7         0.0207  4         0.0119  3         0.0087  7         0.0204  6         0.0174  4         0.0117  4         0.0117  ha_mroonga::generic_ft_init_ext(unsigned int, un
signed int, String*)
0              0  1         0.0030  0              0  1         0.0029  1         0.0029  1         0.0029  0              0  2         0.0059  ha_mroonga::info(unsigned int)
0              0  1         0.0030  2         0.0059  0              0  3         0.0087  2         0.0058  4         0.0117  2         0.0059  ha_mroonga::rebind_psi()
0              0  1         0.0030  1         0.0030  0              0  2         0.0058  1         0.0029  3         0.0088  1         0.0029  ha_mroonga::records_in_range(unsigned int, st_ke
y_range*, st_key_range*)
0              0  3         0.0089  1         0.0030  1         0.0029  0              0  2         0.0058  1         0.0029  5         0.0147  ha_mroonga::rnd_pos(unsigned char*, unsigned cha
r*)
0              0  0              0  1         0.0030  1         0.0029  0              0  1         0.0029  0              0  0              0  ha_mroonga::storage_external_lock(THD*, int)
0              0  0              0  1         0.0030  0              0  1         0.0029  0              0  0              0  0              0  ha_mroonga::storage_extra(ha_extra_function)
0              0  3         0.0089  1         0.0030  2         0.0058  0              0  1         0.0029  1         0.0029  3         0.0088  ha_mroonga::storage_ft_init()
0              0  0              0  0              0  2         0.0058  0              0  1         0.0029  0              0  3         0.0088  ha_mroonga::storage_info_variable()
0              0  1         0.0030  1         0.0030  1         0.0029  0              0  0              0  0              0  0              0  ha_mroonga::storage_info_variable_records()
0              0  0              0  1         0.0030  1         0.0029  1         0.0029  1         0.0029  1         0.0029  0              0  ha_mroonga::storage_primary_key_is_clustered()
0              0  1         0.0030  2         0.0059  4         0.0116  0              0  1         0.0029  0              0  0              0  ha_mroonga::storage_rnd_end()
0              0  1         0.0030  0              0  0              0  0              0  1         0.0029  1         0.0029  0              0  ha_mroonga::storage_unbind_psi()
0              0  2         0.0059  3         0.0089  2         0.0058  2         0.0058  2         0.0058  2         0.0059  3         0.0088  mrn::ConditionConverter::find_match_against(Item
 const*)
0              0  1         0.0030  0              0  0              0  0              0  2         0.0058  0              0  0              0  mrn::ConditionConverter::is_convertable(Item_con
d const*)
0              0  2         0.0059  1         0.0030  1         0.0029  2         0.0058  2         0.0058  2         0.0059  0              0  mrn::MatchEscalationThresholdScope::MatchEscalat
ionThresholdScope(_grn_ctx*, long long)
0              0  0              0  2         0.0059  1         0.0029  2         0.0058  3         0.0087  2         0.0059  2         0.0059  mrn::MatchEscalationThresholdScope::~MatchEscala
tionThresholdScope()
0              0  1         0.0030  0              0  0              0  1         0.0029  1         0.0029  0              0  0              0  mrn::MultipleColumnKeyCodec::~MultipleColumnKeyC
odec()
0              0  0              0  1         0.0030  0              0  0              0  1         0.0029  2         0.0059  2         0.0059  mrn_storage_ft_close_search
  • mrn_storage_ft_get_relevance が突出して時間かかっていることがわかる。

#26 Updated by Kenji Maruyama almost 4 years ago

http://redmine.groonga.org/issues/2335#note-25 の仮想環境におけるOProfileのコールグラフがうまく動かないので、166の実環境でcallgrindを使って同じように"bench.pl 8"をプロファイリングしてみました。

valgrind --tool=callgrind mysqld --datadir=/home/mmmaru777/mysql/mroonga --socket=/home/mmmaru777/mysql/mroonga/mysql.sock --gdb
  • 結果の添付ファイルは以下のGUIツールで見ることができます。
kcachegrind callgrind.out.3073

callgrind_1.png

callgrind_2.png

http://redmine.groonga.org/issues/2335#note-25 とは異なる結果になっています。(こちらはDebugモード, http://redmine.groonga.org/issues/2335#note-25は仮想環境上でこのチケットのインストール手順に従ったrpmインストール)

添付図より、mrn::TimeConverter::grn_time_to_mysql_time と ha_mroonga::storage_store_filed_integer, ha_mroonga::storage_store_filed_blog の順に時間がかかっていることがわかります。

callgrind_3.png

また、http://redmine.groonga.org/issues/2335#note-25 で突出していたmrn_storage_ft_get_relevance のコールグラフをみてみると mrn_change_encoding に時間がかかっていることがわかります。

#27 Updated by Kouhei Sutou almost 4 years ago

あまり良く見ていませんが、プロファイルを見る方法ではなんかうまくいってない雰囲気を感じました!

まずは、使っているSQL↓を小さくしていってどれが原因かを調べるのはいかがでしょうか!?

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id
       FROM article_index_0099
       WHERE blog_id=30 AND
             status=1 AND
             MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE)
       ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

OREDER BY LIMIT を削る。→ 再現したら ORDER BY LIMIT は関係ないことがわかる。

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id
       FROM article_index_0099
       WHERE blog_id=30 AND
             status=1 AND
             MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE);

MATCH AGAINST を削る。→ 再現したら MATCH AGAINST が関係ないことがわかる。(再現しなさそう。)

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id
       FROM article_index_0099
       WHERE blog_id=30 AND
             status=1
       ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

XXX = YYY を削る。 → 再現したら XXX = YYY は関係ないことがわかる。

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE)
       ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

SQL_CALC_FOUND_ROWS を削る。 → 再現したら SQL_CALC_FOUND_ROWS は関係ないことがわかる。

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE blog_id=30 AND
             status=1 AND
             MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE)
       ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0;

他にもパターンはありますが、まずはこのくらい絞り込むのはどうでしょうか!?

#28 Updated by Kenji Maruyama almost 4 years ago

まずはこのくらい絞り込むのはどうでしょうか!?

ありがとうございます。条件文の絞込みでシンプルなクエリでの再現を目指してみます。

#29 Updated by Kenji Maruyama almost 4 years ago

以下クエリで再現しました。

SELECT SQL_NO_CACHE article_id 
       FROM article_index_0099 
       WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",?,")") IN BOOLEAN MODE);

ちなみに SQL_NO_CACHE を外すとキャッシュありだとさすがに早い。

SELECT article_id 
       FROM article_index_0099 
       WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",?,")") IN BOOLEAN MODE);
[vagrant@localhost mrn_concurrent]$ perl bench.pl 1
done: 1.023197889328
[vagrant@localhost mrn_concurrent]$ perl bench.pl 2
done: 1.04841995239258
[vagrant@localhost mrn_concurrent]$ perl bench.pl 3
done: 0.891174077987671
[vagrant@localhost mrn_concurrent]$ perl bench.pl 4
done: 0.857400894165039
[vagrant@localhost mrn_concurrent]$ perl bench.pl 5
done: 0.881013870239258
[vagrant@localhost mrn_concurrent]$ perl bench.pl 6
done: 0.949200868606567
[vagrant@localhost mrn_concurrent]$ perl bench.pl 7
done: 1.18967199325562
[vagrant@localhost mrn_concurrent]$ perl bench.pl 8
done: 1.38302397727966

#30 Updated by Kenji Maruyama almost 4 years ago

以下クエリで再現しました。

シンプルなクエリで再度プロファイリングしてみます。

#31 Updated by Kenji Maruyama almost 4 years ago

シンプルなクエリによる http://redmine.groonga.org/issues/2335#note-25 の再度プロファイリング

Profiling through timer interrupt
Processes with a thread ID of 5185
Processes with a thread ID of 5186
Processes with a thread ID of 5187
Processes with a thread ID of 5188
Processes with a thread ID of 5189
Processes with a thread ID of 5190
Processes with a thread ID of 5191
Processes with a thread ID of 5192
samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        samples  %        symbol name
9342     67.2280  9114     67.7017  9169     68.8208  8877     66.9710  9197     67.4514  7694     67.2729  8174     67.8228  8767     66.7555  mrn_storage_ft_get_relevance
2058     14.8100  2052     15.2429  1880     14.1109  1935     14.5983  1995     14.6315  1718     15.0214  1770     14.6864  1925     14.6577  ha_mroonga::storage_store_fields(unsigned char*,
 unsigned int)
503       3.6197  432       3.2090  449       3.3701  474       3.5760  462       3.3883  362       3.1652  387       3.2111  482       3.6701  ha_mroonga::storage_store_field_integer(Field*,
char const*, unsigned int)
474       3.4111  469       3.4839  354       2.6571  459       3.4628  454       3.3297  397       3.4712  328       2.7215  463       3.5255  ha_mroonga::storage_store_field_blob(Field*, cha
r const*, unsigned int)
383       2.7562  337       2.5033  342       2.5670  345       2.6028  365       2.6769  306       2.6755  312       2.5888  326       2.4823  ha_mroonga::storage_ft_read(unsigned char*)
281       2.0222  275       2.0428  286       2.1467  321       2.4217  303       2.2222  241       2.1072  279       2.3150  297       2.2615  ha_mroonga::storage_store_field(Field*, char con
st*, unsigned int)
201       1.4465  160       1.1885  151       1.1334  172       1.2976  198       1.4521  164       1.4339  176       1.4603  225       1.7132  ha_mroonga::ft_read(unsigned char*)
191       1.3745  158       1.1737  194       1.4561  172       1.2976  157       1.1514  161       1.4077  186       1.5433  175       1.3325  mrn::encoding::set(_grn_ctx*, charset_info_st co
nst*)
162       1.1658  164       1.2182  187       1.4036  178       1.3429  181       1.3275  138       1.2066  159       1.3193  179       1.3630  mrn_change_encoding
111       0.7988  93        0.6908  109       0.8181  105       0.7922  116       0.8508  99        0.8656  111       0.9210  89        0.6777  mrn::DebugColumnAccess::DebugColumnAccess(TABLE*
, st_bitmap*)
54        0.3886  61        0.4531  66        0.4954  70        0.5281  51        0.3740  41        0.3585  65        0.5393  61        0.4645  ha_mroonga::storage_scan_time()
54        0.3886  66        0.4903  72        0.5404  67        0.5055  69        0.5061  45        0.3935  52        0.4315  59        0.4492  mrn::DebugColumnAccess::~DebugColumnAccess()
8         0.0576  7         0.0520  3         0.0225  7         0.0528  6         0.0440  14        0.1224  7         0.0581  8         0.0609  ha_mroonga::generic_ft_init_ext_select(unsigned
int, unsigned int, String*)
5         0.0360  2         0.0149  2         0.0150  1         0.0075  2         0.0147  2         0.0175  0              0  2         0.0152  ha_mroonga::storage_info(unsigned int)
4         0.0288  2         0.0149  3         0.0225  3         0.0226  3         0.0220  1         0.0087  1         0.0083  4         0.0305  ha_mroonga::check_fast_order_limit(_grn_table_so
rt_key**, int*, long long*)
4         0.0288  0              0  0              0  3         0.0226  0              0  0              0  2         0.0166  1         0.0076  ha_mroonga::generic_extra(ha_extra_function)
4         0.0288  2         0.0149  5         0.0375  5         0.0377  5         0.0367  2         0.0175  3         0.0249  5         0.0381  ha_mroonga::generic_ft_init_ext(unsigned int, un
signed int, String*)
4         0.0288  0              0  3         0.0225  5         0.0377  2         0.0147  1         0.0087  2         0.0166  7         0.0533  ha_mroonga::is_enable_optimization()
3         0.0216  2         0.0149  0              0  2         0.0151  0              0  1         0.0087  4         0.0332  1         0.0076  ha_mroonga::check_count_skip(unsigned long, unsi
gned long, bool)
3         0.0216  2         0.0149  0              0  0              0  4         0.0293  4         0.0350  1         0.0083  0              0  mrn::MatchEscalationThresholdScope::~MatchEscala
tionThresholdScope()
2         0.0144  1         0.0074  1         0.0075  0              0  0              0  1         0.0087  1         0.0083  2         0.0152  ha_mroonga::file_size(char const*)
2         0.0144  2         0.0149  0              0  1         0.0075  2         0.0147  2         0.0175  2         0.0166  1         0.0076  ha_mroonga::generic_ft_init_ext_prepare_expressi
on_in_boolean_mode(st_mrn_ft_info*, String*, _grn_obj*, _grn_obj*, _grn_obj*, _grn_obj*)
2         0.0144  5         0.0371  3         0.0225  3         0.0226  3         0.0220  4         0.0350  0              0  1         0.0076  ha_mroonga::generic_reset()
2         0.0144  1         0.0074  0              0  1         0.0075  2         0.0147  2         0.0175  0              0  1         0.0076  ha_mroonga::index_init(unsigned int, bool)
2         0.0144  4         0.0297  1         0.0075  1         0.0075  1         0.0073  1         0.0087  1         0.0083  4         0.0305  ha_mroonga::storage_cond_push(Item const*)
2         0.0144  1         0.0074  2         0.0150  0              0  0              0  1         0.0087  0              0  1         0.0076  ha_mroonga::storage_extra(ha_extra_function)
2         0.0144  1         0.0074  0              0  1         0.0075  0              0  0              0  0              0  0              0  ha_mroonga::storage_ft_init()
2         0.0144  1         0.0074  4         0.0300  2         0.0151  1         0.0073  0              0  0              0  1         0.0076  ha_mroonga::storage_index_init(unsigned int, bool)
2         0.0144  2         0.0149  3         0.0225  4         0.0302  6         0.0440  2         0.0175  4         0.0332  4         0.0305  ha_mroonga::storage_info_variable_data_file_length
()
2         0.0144  1         0.0074  3         0.0225  1         0.0075  1         0.0073  1         0.0087  1         0.0083  2         0.0152  ha_mroonga::storage_store_lock(THD*, st_thr_lock_d
ata**, thr_lock_type)
2         0.0144  0              0  1         0.0075  1         0.0075  0              0  1         0.0087  0              0  2         0.0152  mrn::ConditionConverter::is_convertable(Item_func
const*)
2         0.0144  1         0.0074  2         0.0150  3         0.0226  2         0.0147  0              0  0              0  3         0.0228  mrn_clear_alter_share
1         0.0072  0              0  1         0.0075  2         0.0151  1         0.0073  3         0.0262  1         0.0083  2         0.0152  ha_mroonga::clear_cursor()
1         0.0072  1         0.0074  1         0.0075  1         0.0075  4         0.0293  2         0.0175  1         0.0083  1         0.0076  ha_mroonga::clear_cursor_geo()
1         0.0072  0              0  0              0  0              0  1         0.0073  0              0  0              0  0              0  ha_mroonga::clear_search_result()
1         0.0072  1         0.0074  1         0.0075  3         0.0226  0              0  1         0.0087  1         0.0083  0              0  ha_mroonga::cond_push(Item const*)
1         0.0072  0              0  2         0.0150  0              0  4         0.0293  0              0  0              0  1         0.0076  ha_mroonga::external_lock(THD*, int)
1         0.0072  1         0.0074  1         0.0075  0              0  4         0.0293  3         0.0262  2         0.0166  1         0.0076  ha_mroonga::extra(ha_extra_function)
1         0.0072  2         0.0149  1         0.0075  4         0.0302  2         0.0147  1         0.0087  0              0  1         0.0076  ha_mroonga::ft_init_ext(unsigned int, unsigned int
, String*)
1         0.0072  2         0.0149  1         0.0075  3         0.0226  5         0.0367  1         0.0087  0              0  1         0.0076  ha_mroonga::generic_ft_init()
1         0.0072  0              0  1         0.0075  0              0  0              0  0              0  1         0.0083  0              0  ha_mroonga::index_end()
1         0.0072  0              0  0              0  0              0  0              0  2         0.0175  0              0  2         0.0152  ha_mroonga::info(unsigned int)
1         0.0072  1         0.0074  0              0  1         0.0075  0              0  2         0.0175  1         0.0083  4         0.0305  ha_mroonga::reset()
1         0.0072  2         0.0149  1         0.0075  3         0.0226  2         0.0147  1         0.0087  2         0.0166  2         0.0152  ha_mroonga::scan_time()
1         0.0072  4         0.0297  0              0  0              0  2         0.0147  0              0  1         0.0083  3         0.0228  ha_mroonga::storage_ft_init_ext(unsigned int, unsi
gned int, String*)
1         0.0072  2         0.0149  0              0  0              0  0              0  1         0.0087  2         0.0166  1         0.0076  ha_mroonga::storage_info_variable()
1         0.0072  1         0.0074  0              0  1         0.0075  1         0.0073  0              0  1         0.0083  1         0.0076  ha_mroonga::storage_info_variable_records()
1         0.0072  3         0.0223  0              0  0              0  1         0.0073  0              0  0              0  0              0  ha_mroonga::storage_table_flags() const
1         0.0072  2         0.0149  0              0  1         0.0075  0              0  1         0.0087  0              0  0              0  ha_mroonga::store_lock(THD*, st_thr_lock_data**, t
hr_lock_type)
1         0.0072  0              0  0              0  2         0.0151  1         0.0073  0              0  0              0  1         0.0076  mrn::ConditionConverter::ConditionConverter(_grn_c
tx*, _grn_obj*, bool)
1         0.0072  2         0.0149  0              0  0              0  0              0  1         0.0087  0              0  1         0.0076  mrn::ConditionConverter::find_match_against(Item c
onst*)
1         0.0072  2         0.0149  0              0  1         0.0075  1         0.0073  4         0.0350  2         0.0166  1         0.0076  mrn::ConditionConverter::is_convertable(Item const
*)
1         0.0072  1         0.0074  3         0.0225  1         0.0075  1         0.0073  0              0  0              0  2         0.0152  mrn::ConditionConverter::~ConditionConverter()
1         0.0072  0              0  0              0  3         0.0226  5         0.0367  1         0.0087  0              0  0              0  mrn_get_slot_data
1         0.0072  1         0.0074  1         0.0075  0              0  0              0  0              0  0              0  0              0  mrn_storage_ft_close_search
0              0  1         0.0074  1         0.0075  0              0  0              0  0              0  0              0  0              0  ha_mroonga::clear_empty_value_records()
0              0  0              0  3         0.0225  0              0  1         0.0073  1         0.0087  0              0  0              0  ha_mroonga::clear_search_result_geo()
0              0  1         0.0074  0              0  0              0  0              0  0              0  0              0  0              0  ha_mroonga::ft_init()
0              0  0              0  0              0  0              0  2         0.0147  2         0.0175  1         0.0083  1         0.0076  ha_mroonga::lock_count() const
0              0  1         0.0074  1         0.0075  0              0  4         0.0293  1         0.0087  3         0.0249  3         0.0228  ha_mroonga::rebind_psi()
0              0  1         0.0074  1         0.0075  1         0.0075  0              0  1         0.0087  1         0.0083  0              0  ha_mroonga::storage_external_lock(THD*, int)
0              0  4         0.0297  4         0.0300  1         0.0075  0              0  0              0  1         0.0083  0              0  ha_mroonga::storage_index_end()
0              0  0              0  0              0  0              0  0              0  0              0  2         0.0166  0              0  ha_mroonga::storage_lock_count() const
0              0  0              0  1         0.0075  0              0  0              0  0              0  0              0  1         0.0076  ha_mroonga::storage_rebind_psi()
0              0  2         0.0149  0              0  0              0  0              0  0              0  0              0  1         0.0076  ha_mroonga::storage_reset()
0              0  0              0  0              0  1         0.0075  0              0  0              0  0              0  0              0  ha_mroonga::storage_unbind_psi()
0              0  6         0.0446  2         0.0150  3         0.0226  3         0.0220  0              0  1         0.0083  3         0.0228  ha_mroonga::table_flags() const
0              0  0              0  0              0  2         0.0151  2         0.0147  0              0  0              0  0              0  ha_mroonga::unbind_psi()
0              0  0              0  0              0  0              0  0              0  1         0.0087  0              0  0              0  mrn::MatchEscalationThresholdScope::MatchEscalatio
nThresholdScope(_grn_ctx*, long long)
0              0  0              0  1         0.0075  2         0.0151  0              0  1         0.0087  0              0  1         0.0076  mrn_generic_ft_clear

#32 Updated by Kenji Maruyama almost 4 years ago

http://redmine.groonga.org/issues/2335#note-26 を再度プロファイリング

callgrind_4.png

callgrind_5.png

ha_mroonga::storage_store_field_blob のコールグラフを見てみると、String::q_appendで時間がかかっていることがわかる。

#33 Updated by Kouhei Sutou almost 4 years ago

mrn_storage_ft_get_relevance()が遅いということなので、↓をコメントアウトして

https://github.com/mroonga/mroonga/blob/master/ha_mroonga.cpp#L1659-1667

    grn_id result_record_id;
    result_record_id = grn_table_get(info->ctx, info->result,
                                     &(mroonga->record_id), sizeof(grn_id));
    if (result_record_id != GRN_ID_NIL) {
      GRN_BULK_REWIND(&(info->score));
      grn_obj_get_value(info->ctx, info->score_column,
                        result_record_id, &(info->score));
      score = (float)GRN_INT32_VALUE(&(info->score));
    }

つねに score = 1.0 とするとどうでしょうか!?

#34 Updated by Kouhei Sutou almost 4 years ago

念のため書いておくと、 score = 1.0 するだけにして問題が再現しなくなるならコメントアウトしたコードの中に原因があります。

もし、再現しなくなるなら次は

    if (result_record_id != GRN_ID_NIL) {
      GRN_BULK_REWIND(&(info->score));
      grn_obj_get_value(info->ctx, info->score_column,
                        result_record_id, &(info->score));
      score = (float)GRN_INT32_VALUE(&(info->score));
    }

をコメントアウトして、ここを score = 1.0 に置き換えます。これで再現するようになればコメントアウトせずに残している

    grn_id result_record_id;
    result_record_id = grn_table_get(info->ctx, info->result,
                                     &(mroonga->record_id), sizeof(grn_id));

が原因です。次に調べるのは grn_table_get の中ということですね。

一方、再現しないままなら

      GRN_BULK_REWIND(&(info->score));
      grn_obj_get_value(info->ctx, info->score_column,
                        result_record_id, &(info->score));
      score = (float)GRN_INT32_VALUE(&(info->score));

の中に原因があります。この場合は、たぶん、 grn_obj_get_value でしょう。

もし、そもそもこのあたり全部をコメントアウトしても問題が再現したままならmrn_storage_ft_get_relevance()は関係ありません。念のため、中身を score = 1.0 にしたままもう一回プロファイルをとりましょう。

#35 Updated by Kenji Maruyama almost 4 years ago

score = 1.0 とするとどうでしょうか!?

http://redmine.groonga.org/issues/2335#note-25 の OProfile 環境はMroongaのrpm版(仮想環境)なので、中身を score = 1.0 にする、 score = 1.0 にしたままもう一回プロファイル は難しそうなので、実環境、ソースデバッグモードでやってみたところ、全部をコメントアウトしても問題は再現したままです。

実環境、ソースデバッグモードでのプロファイリング結果は http://redmine.groonga.org/issues/2335#note-26 になりますが、違うプロファイラーを使っているため両者違うものになっています。(OProfileがコールグラフうまく取れないためCallgrindを使っています) Mroongaのベンチマークの結果は環境変えてもほぼ同じです。

#36 Updated by Kenji Maruyama almost 4 years ago

比較対象参考までに以下の環境で"SHOW profile ALL"

シンプルなクエリ(http://redmine.groonga.org/issues/2335#note-29 ), 実環境, my.cnf デフォルト (今までのmy.cnfはカスタマ イズされている), perl bench.pl 8

プロファイリングの結果、時間がかかったクエリを一つ取り出してMroongaとInnoDBを比較

+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file      | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+

Mroonga

starting    0.000560    0.000000    0.004000    52  0   0   0   0   0   0   0   0
checking permissions    0.000052    0.000000    0.000000    4   0   0   0   0   0   0   0   0   check_access    sql_parse.cc    5225
Opening tables  0.000154    0.000000    0.004001    17  0   0   0   0   0   0   0   0   open_tables sql_base.cc 4911
init    0.000219    0.000000    0.000000    27  0   0   0   0   0   0   0   0   mysql_prepare_select    sql_select.cc   1050
System lock 0.000072    0.000000    0.000000    7   0   0   0   0   0   0   0   0   mysql_lock_tables   lock.cc 304
optimizing  0.000119    0.000000    0.004000    9   0   0   0   0   0   0   0   0   optimize    sql_optimizer.cc    138
statistics  0.000308    0.000000    0.000000    28  0   0   0   0   0   0   11  0   optimize    sql_optimizer.cc    381
preparing   0.000149    0.000000    0.000000    17  0   0   0   0   0   0   0   0   optimize    sql_optimizer.cc    500
FULLTEXT initialization 0.000930    0.000000    0.008000    83  0   0   0   0   0   0   36  0   init_ftfuncs    sql_base.cc 9245
executing   0.000009    0.000000    0.000000    1   0   0   0   0   0   0   0   0   exec    sql_executor.cc 110
Sending data     0.122402       0.200012    0.748047    12193   80  0   0   0   0   0   331 0   exec    sql_executor.cc 187
end 0.000092    0.000000    0.000000    6   0   0   0   0   0   0   0   0   mysql_execute_select    sql_select.cc   1105
query end   0.000112    0.000000    0.000000    13  0   0   0   0   0   0   0   0   mysql_execute_command   sql_parse.cc    4935
closing tables  0.000331    0.000000    0.004000    30  0   0   0   0   0   0   0   0   mysql_execute_command   sql_parse.cc    4983
freeing items   0.000155    0.000000    0.000000    15  0   0   0   0   0   0   0   0   mysql_parse sql_parse.cc    6233
cleaning up 0.000066    0.004001    0.000000    6   0   0   0   0   0   0   0   0   dispatch_command    sql_parse.cc    1760

done: 131.332741975784

InnoDB

starting    0.000180    0.000000    0.000000    20  0   0   0   0   0   0   0   0
checking permissions    0.000038    0.000000    0.000000    2   0   0   0   0   0   0   0   0   check_access    sql_parse.cc    5225
Opening tables  0.000018    0.000000    0.000000    0   0   0   0   0   0   0   0   0   open_tables sql_base.cc 4911
init    0.000063    0.000000    0.000000    4   0   0   0   0   0   0   0   0   mysql_prepare_select    sql_select.cc   1050
System lock 0.000013    0.000000    0.000000    0   0   0   0   0   0   0   0   0   mysql_lock_tables   lock.cc 304
optimizing  0.000038    0.000000    0.000000    1   0   0   0   0   0   0   0   0   optimize    sql_optimizer.cc    138
statistics  0.000055    0.004001    0.000000    4   0   0   0   0   0   0   0   0   optimize    sql_optimizer.cc    381
preparing   0.000040    0.000000    0.000000    2   0   0   0   0   0   0   0   0   optimize    sql_optimizer.cc    500
FULLTEXT initialization 0.005877    0.044002    0.000000    222 5   0   0   0   0   0   0   0   init_ftfuncs    sql_base.cc 9245
executing   0.000009    0.000000    0.000000    0   0   0   0   0   0   0   0   0   exec    sql_executor.cc 110
Sending data        0.057049    0.372024    0.052003    2542     36 0   0   0   0   0   0   0   exec    sql_executor.cc 187
end 0.000054    0.000000    0.004000    3   0   0   0   0   0   0   0   0   mysql_execute_select    sql_select.cc   1105
query end   0.000019    0.000000    0.000000    0   0   0   0   0   0   0   0   0   mysql_execute_command   sql_parse.cc    4935
closing tables  0.000062    0.000000    0.000000    5   0   0   0   0   0   0   0   0   mysql_execute_command   sql_parse.cc    4983
freeing items   0.000611    0.000000    0.004000    31  0   0   0   0   0   0   0   0   mysql_parse sql_parse.cc    6233
cleaning up 0.000031    0.000000    0.000000    1   0   0   0   0   0   0   0   0   dispatch_command    sql_parse.cc    1760

done: 71.8816421031952

  • どちらもSending data(検索、検索結果をクライアントに送信)で一番時間がかかり、MroongaはInnoDBに対してContext_voluntary(コンテキストスイッチング回数)で6倍, CPU_system時間で10倍以上時間かかっている。

#37 Updated by Kouhei Sutou almost 4 years ago

Kenji Maruyama wrote:

http://redmine.groonga.org/issues/2335#note-25 の OProfile 環境はMroongaのrpm版(仮想環境)なので、中身を score = 1.0 にする、 score = 1.0 にしたままもう一回プロファイル は難しそうなので、実環境、ソースデバッグモードでやってみたところ、全部をコメントアウトしても問題は再現したままです。

デバッグモードで再現できることがわかっているのでRPM版はもう試さなくていいです!RPM版を試すときは、問題を修正して、問題が直っていることを確認するときだけで十分です!

#38 Updated by Kenji Maruyama almost 4 years ago

デバッグモードで再現できることがわかっているのでRPM版はもう試さなくていいです!RPM版を試すときは、問題を修正して、問題が直っていることを確認するときだけで十分です!

了解です。プロファイラーがDebug BuildとRPM とで結果が違うので、両方で試していました。Debug Buildだけで良いかもしれません。

#39 Updated by Kouhei Sutou almost 4 years ago

MyISAM, InnoDB, Mroongaそれぞれで以下を実行するとどうなりますか?

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE);

#40 Updated by Kenji Maruyama almost 4 years ago

MyISAM, InnoDB, Mroongaそれぞれで以下を実行するとどうなりますか?

了解です。やってみます。

#41 Updated by Kenji Maruyama almost 4 years ago

打ち合わせにて以下も合わせて検証してみます。

  • GroongaServerのCPU使用率計測
  • 単一プロセスのCPU使用率計測
  • OProfile ロックカウント
  • mutex あたりのコメントアウトするとどうなるか
  • 自然文検索で再現できるか

#42 Updated by daijiro MORI almost 4 years ago

mutexでなくてfutexです。でも優先度低いです。 nlq-searchでどうなるか、というのもそうですが、 似たようなクエリで、再現するパタン、しないパタンがいろいろ見つけられると有用だと思います。 いろいろ試すと良いと思います。

#43 Updated by Kouhei Sutou almost 4 years ago

Kouhei Sutou wrote:

MyISAM, InnoDB, Mroongaそれぞれで以下を実行するとどうなりますか?

SELECT SQL_NO_CACHE article_id
FROM article_index_0099
WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE);

すみません! EXPLAIN つけるの忘れました!

EXPLAIN SELECT SQL_NO_CACHE article_id
        FROM article_index_0099
        WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE);

あと、ついでに、これらお願いします!

EXPLAIN SELECT SQL_NO_CACHE article_id
        FROM article_index_0099
        WHERE MATCH(public_terms) AGAINST("+(livedoor blog)") IN BOOLEAN MODE);

さらに、これはMroongaだけでいいんですけど、このクエリーでも問題が再現するか確認してもらえませんか?

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+livedoor +blog") IN BOOLEAN MODE);

#44 Updated by Kenji Maruyama almost 4 years ago

mysql> EXPLAIN SELECT SQL_NO_CACHE article_id FROM article_index_0099 WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",'livedoor ブログ blog 開発',")") IN BOOLEAN MODE);

Mroonga
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra                             |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where with pushed condition |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
1 row in set (0.00 sec)

MyISAM
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra       |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
1 row in set (0.00 sec)

InnoDB
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra       |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
1 row in set (0.00 sec)


mysql> EXPLAIN SELECT SQL_NO_CACHE article_id FROM article_index_0099 WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

Mroonga
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra                             |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where with pushed condition |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-----------------------------------+
1 row in set (0.00 sec)

MyISAM
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra       |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
1 row in set (0.00 sec)


InnoDB
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
| id | select_type | table              | type     | possible_keys | key        | key_len | ref  | rows | Extra       |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
|  1 | SIMPLE      | article_index_0099 | fulltext | for_public    | for_public | 0       | NULL |    1 | Using where |
+----+-------------+--------------------+----------+---------------+------------+---------+------+------+-------------+
1 row in set (0.00 sec)

以下のSQLをMroongaで実行した結果になります。CONCAT_WSを外すと再現しません。

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+livedoor +blog" IN BOOLEAN MODE);
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 1
done: 2.63545513153076
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 2
done: 3.41241788864136
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 3
done: 4.16580700874329
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 4
done: 5.40642595291138
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 5
done: 6.7235369682312
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 6
done: 8.13963913917542
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 7
done: 9.4711639881134
mmmaru777@s37:~/mrn_bugs/2335$ perl 1.pl 8
done: 11.2861151695251

#45 Updated by Kouhei Sutou almost 4 years ago

Kenji Maruyama wrote:

以下のSQLをMroongaで実行した結果になります。CONCAT_WSを外すと再現しません。

うぉー!怪しげですね!

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

とするとどうですか!?

また、 +livedoor +blog をRPM版で試すとどうですか!?そっちも再現しませんか?

#46 Updated by Kenji Maruyama almost 4 years ago

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

結果は以下です。再現しません!

mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 1
done: 1.97440195083618
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 2
done: 2.5368390083313
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 3
done: 2.9918200969696
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 4
done: 4.09118103981018
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 5
done: 5.10622406005859
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 6
done: 5.27606701850891
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 7
done: 5.82945799827576
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_2.pl 8
done: 6.53114604949951

#47 Updated by Kouhei Sutou almost 4 years ago

Kenji Maruyama wrote:


SELECT SQL_NO_CACHE article_id
FROM article_index_0099
WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

結果は以下です。再現しません!

おぉ!念のため、これも試してもらえませんか?

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor ブログ blog 開発)" IN BOOLEAN MODE);

#48 Updated by Kenji Maruyama almost 4 years ago

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor ブログ blog 開発)" IN BOOLEAN MODE);

これだと再現しますね.

mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 1
done: 12.100063085556
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 2
done: 27.7694909572601
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 3
done: 45.4597249031067
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 4
done: 69.1042070388794
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 5
done: 87.6652081012726
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 6
done: 99.8292810916901
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 7
done: 112.721530914307
mmmaru777@s37:~/mrn_bugs/2335$ perl plus_plus_3.pl 8
done: 127.261954069138

#49 Updated by Kenji Maruyama almost 4 years ago

+livedoor +blog をRPM版で試すとどうですか!?そっちも再現しませんか?

RPM版 (仮想環境)

再現します。むしろ遅くなります。

[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 1
done: 3.85584115982056
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 2
done: 41.7754909992218
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 3
done: 84.6350340843201
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 4
done: 120.204046010971
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 5
done: 156.662518978119
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 6
done: 165.902009010315
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 7
done: 181.822917938232
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 8
done: 259.97222495079

#50 Updated by Kenji Maruyama almost 4 years ago

+(livedoor ブログ blog 開発) はRPM版環境でも再現する。

整理すると、

CONCAT_WSを外して、+livedoor +blog だと実環境でMroonga Git Master版では再現しない、仮想環境でMroonga RPM版は再現する。

CONCAT_WSを外して、+(livedoor ブログ blog 開発) だと実環境でMroonga Git Master版で再現する。仮想環境でMroonga RPM版は再現する。

#51 Updated by Kenji Maruyama almost 4 years ago

+(ブログ 開発) の場合も試してみると、

実環境でMroonga Git Master版では再現しない. 仮想環境でMroonga RPM版は再現する。

#52 Updated by Kenji Maruyama almost 4 years ago

BOOLEAN MODEを外して以下のクエリらは 実環境でMroonga Git Master版で再現する。

   SELECT SQL_NO_CACHE article_id 
       FROM article_index_0099 
       WHERE MATCH(public_terms) AGAINST("livedoor blog");
   SELECT SQL_NO_CACHE article_id 
       FROM article_index_0099 
       WHERE MATCH(public_terms) AGAINST("livedoor");

#53 Updated by Kouhei Sutou almost 4 years ago

+(livedoor blog)+(ブログ 開発) が再現しないの、変な感じですね。

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+livedoor +blog" IN BOOLEAN MODE);

の検索結果は同じですか?

同様に

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(ブログ 開発)" IN BOOLEAN MODE);

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+ブログ +開発" IN BOOLEAN MODE);

の検索結果は同じですか?

Mroongaは先頭の + を無視するようにしていた気がするので (...) はOR検索で +... +... はAND検索になってしまっている気がします。

#54 Updated by Kouhei Sutou almost 4 years ago

あと、

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+livedoor +blog" IN BOOLEAN MODE);

を1回だけ実行した時のトレースログをとってもらえますか?

% mysqld ... --debug=d:t:i:A,/tmp/mroonga.trace

というように起動すればとれるはずです。

同じように、InnoDBで同じクエリーを1回だけ実行した場合もとってください。

とったら、2つを比べましょう。ストレージエンジンごとの処理(MroongaとInnoDBの処理)は無視して、MySQLレベルの処理だけ比較します。全文検索より前と全文検索後の処理は完全に一致すると思います。一方、全文検索中の処理(関数名にftが入っているようなやつら)で違いがあるんじゃないかと思います。

というのは、InnoDBでは再現していなくて、Mroongaでは再現しているので、InnoDBの方だけが何か並列実行に有利になるようなパラメーターを渡してMySQLレベルの最適化が聞いているんじゃないかと思うからです。もし、この予想が当たっていれば、全文検索まわりのMySQLレベルの処理(MroongaとかInnoDBとかストレージエンジン特有の処理は無視)にだけ違いがでると思います。当たっていなければ、違いはないと思います!

#55 Updated by Kenji Maruyama almost 4 years ago

+(livedoor blog)+(ブログ 開発) が再現しないの、変な感じですね。

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor blog)" IN BOOLEAN MODE);

1415 rows in set (0.01 sec)

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+livedoor +blog" IN BOOLEAN MODE);

1222 rows in set (0.02 sec)

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(ブログ 開発)" IN BOOLEAN MODE);

1084 rows in set (0.01 sec)

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+ブログ +開発" IN BOOLEAN MODE);

100 rows in set (0.01 sec)

Mroongaは先頭の + を無視するようにしていた気がするので (...) はOR検索で +... +... はAND検索になってしまっている気がします。

結果の件数をみるとそうなっているように見えます。実際に検索結果を出してみるとそうなっています。

トレースログをとってもらえますか?

なるほどです。

+livedoor +blog のMroongaとInnoDBのトレースログ比較してみます。

#56 Updated by Kenji Maruyama almost 4 years ago

+livedoor +blog のMroongaとInnoDBのトレースログ比較してみます。

+livedoor +blog は実環境だと再現しないパターンですね。実環境で両者比較してみました。

差異が目立つ所

  • Mroongaにあって, InnoDBにない処理が主に以下の3つになります。特に前記プロファイリングの結果の上位に出てくる "store_field, ft_get_relevance" がヒットした件数分呼ばれます。(ここが原因だと思われたのですが、+livedoor +blog は実環境だと再現しないパターンなんですよね。)

lock_count.png

cond_push.png

store_field.png

実環境で再現するパターンで同じようにトレースログの差異をみてみます。また、再現しない場合と再現する場合の差異もみてみます。

SELECT SQL_NO_CACHE article_id
       FROM article_index_0099
       WHERE MATCH(public_terms) AGAINST("+(livedoor ブログ blog 開発)" IN BOOLEAN MODE);

#57 Updated by Kouhei Sutou almost 4 years ago

生ログも添付してもらえますか!?(大きかったら圧縮していいです。)

#58 Updated by Kenji Maruyama almost 4 years ago

"+livedoor +blog" のtrace logが mrn.tarce, inno.trace

"+(livedoor ブログ blog 開発)" のtrace logが mrn_slow.trace, inno_slow.trace になります。

#59 Updated by Kenji Maruyama almost 4 years ago

  • クエリ実行結果の件数

"+(livedoor ブログ blog 開発)" Mroongaで再現する場合

  • Mroonga : 1222
  • InnoDB : 1239

"+livedoor +blog" Mroongaで再現しない場合

  • Mroonga : 1482
  • InnoDB : 798

scan_time.png

user_time.png

  • Mroongaで再現しない場合、添付図のtable_scanのコストがInnoDBとMroongaとで異なるが、Mroongaで再現する場合と再現しない場合のこのコストに差は見られませんので、ここは関係なさそうです。

  • Mroongaで再現する場合と再現しない場合のシングルクエリでのUser time, System time、context switchesの値をみると、それほど差異が見られません。

#60 Updated by Kenji Maruyama almost 4 years ago

他の差異がちょっと見つけづらいので、マルチプロセスで"+(livedoor ブログ blog 開発)"の検索クエリを流してみて、今までのシングルプロセスでのトレースログと比較してみます。

#61 Updated by Kenji Maruyama almost 4 years ago

perl bench.pl 1 時の CPU, I/O 負荷

仮想環境

Mroonga

[vagrant@localhost ~]$ sar -P ALL 1 9
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/05/2014  _x86_64_    (8 CPU)

04:55:53 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:54 PM     all      9.15      0.00      3.38      0.00      0.00     87.47
04:55:54 PM       0     42.42      0.00     15.15      0.00      0.00     42.42
04:55:54 PM       1     30.30      0.00     11.11      0.00      0.00     58.59
04:55:54 PM       2      1.01      0.00      0.00      0.00      0.00     98.99
04:55:54 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:54 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:54 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:54 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
04:55:54 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:54 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:55 PM     all      9.05      0.00      3.39      0.00      0.00     87.56
04:55:55 PM       0     30.30      0.00     12.12      0.00      0.00     57.58
04:55:55 PM       1     42.00      0.00     15.00      0.00      0.00     43.00
04:55:55 PM       2      0.00      0.00      0.99      0.00      0.00     99.01
04:55:55 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:55 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:55 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:55 PM       6      0.00      0.00      0.99      0.00      0.00     99.01
04:55:55 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:55 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:56 PM     all      9.40      0.00      3.13      0.00      0.00     87.47
04:55:56 PM       0     64.00      0.00     20.00      0.00      0.00     16.00
04:55:56 PM       1     11.22      0.00      4.08      0.00      0.00     84.69
04:55:56 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
04:55:56 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:56 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:56 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:56 PM       6      1.00      0.00      0.00      0.00      0.00     99.00
04:55:56 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:56 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:57 PM     all      9.27      0.00      3.38      0.00      0.00     87.34
04:55:57 PM       0     31.63      0.00     10.20      0.00      0.00     58.16
04:55:57 PM       1     40.82      0.00     14.29      0.00      0.00     44.90
04:55:57 PM       2      2.00      0.00      1.00      0.00      0.00     97.00
04:55:57 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:57 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:57 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:57 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
04:55:57 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:57 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:58 PM     all      8.91      0.00      3.51      0.00      0.00     87.58
04:55:58 PM       0      8.08      0.00      5.05      0.00      0.00     86.87
04:55:58 PM       1     62.38      0.00     23.76      0.00      0.00     13.86
04:55:58 PM       2      1.01      0.00      0.00      0.00      0.00     98.99
04:55:58 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:58 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:58 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:58 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
04:55:58 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:58 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:55:59 PM     all      9.02      0.00      3.51      0.00      0.00     87.47
04:55:59 PM       0     15.31      0.00      6.12      0.00      0.00     78.57
04:55:59 PM       1     56.00      0.00     20.00      0.00      0.00     24.00
04:55:59 PM       2      0.99      0.00      0.99      0.00      0.00     98.02
04:55:59 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:55:59 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:55:59 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:55:59 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
04:55:59 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:55:59 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:56:00 PM     all      9.03      0.00      3.51      0.00      0.00     87.45
04:56:00 PM       0     54.55      0.00     21.21      0.00      0.00     24.24
04:56:00 PM       1     17.35      0.00      7.14      0.00      0.00     75.51
04:56:00 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
04:56:00 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:56:00 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:56:00 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:56:00 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
04:56:00 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:56:00 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:56:01 PM     all      9.15      0.00      3.38      0.00      0.00     87.47
04:56:01 PM       0     38.78      0.00     12.24      0.00      0.00     48.98
04:56:01 PM       1     35.00      0.00     14.00      0.00      0.00     51.00
04:56:01 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
04:56:01 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
04:56:01 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:56:01 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:56:01 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
04:56:01 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

04:56:01 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
04:56:02 PM     all      8.92      0.00      3.64      0.00      0.00     87.44
04:56:02 PM       0     61.39      0.00     23.76      0.00      0.00     14.85
04:56:02 PM       1     10.10      0.00      5.05      0.00      0.00     84.85
04:56:02 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
04:56:02 PM       3      1.00      0.00      0.00      0.00      0.00     99.00
04:56:02 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
04:56:02 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
04:56:02 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
04:56:02 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all      9.10      0.00      3.43      0.00      0.00     87.47
Average:          0     38.61      0.00     14.03      0.00      0.00     47.36
Average:          1     34.04      0.00     12.77      0.00      0.00     53.19
Average:          2      0.56      0.00      0.33      0.00      0.00     99.11
Average:          3      0.11      0.00      0.00      0.00      0.00     99.89
Average:          4      0.00      0.00      0.00      0.00      0.00    100.00
Average:          5      0.00      0.00      0.00      0.00      0.00    100.00
Average:          6      0.11      0.00      0.44      0.00      0.00     99.44
Average:          7      0.00      0.00      0.00      0.00      0.00    100.00

InnoDB

[vagrant@localhost mrn_concurrent]$ sar -P ALL 1 9
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/05/2014  _x86_64_    (8 CPU)

05:13:26 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:27 PM     all     11.29      0.00      1.38      0.00      0.00     87.33
05:13:27 PM       0     26.00      0.00      5.00      0.00      0.00     69.00
05:13:27 PM       1     64.00      0.00      6.00      0.00      0.00     30.00
05:13:27 PM       2      0.00      0.00      1.00      0.00      0.00     99.00
05:13:27 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:27 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:27 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:27 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
05:13:27 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:27 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:28 PM     all     11.42      0.00      1.00      0.00      0.00     87.58
05:13:28 PM       0      5.10      0.00      4.08      0.00      0.00     90.82
05:13:28 PM       1     86.00      0.00      4.00      0.00      0.00     10.00
05:13:28 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
05:13:28 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:28 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:28 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:28 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
05:13:28 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:28 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:29 PM     all     11.53      0.00      1.00      0.13      0.00     87.34
05:13:29 PM       0      6.12      0.00      4.08      0.00      0.00     89.80
05:13:29 PM       1     86.00      0.00      3.00      0.00      0.00     11.00
05:13:29 PM       2      1.00      0.00      0.00      1.00      0.00     98.00
05:13:29 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:29 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:29 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:29 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
05:13:29 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:29 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:30 PM     all     11.40      0.00      1.13      0.00      0.00     87.47
05:13:30 PM       0      6.06      0.00      3.03      0.00      0.00     90.91
05:13:30 PM       1     83.17      0.00      4.95      0.00      0.00     11.88
05:13:30 PM       2      1.00      0.00      1.00      0.00      0.00     98.00
05:13:30 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:30 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:30 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:30 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
05:13:30 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:30 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:31 PM     all     11.67      0.00      0.88      0.00      0.00     87.45
05:13:31 PM       0     41.84      0.00      3.06      0.00      0.00     55.10
05:13:31 PM       1     52.04      0.00      3.06      0.00      0.00     44.90
05:13:31 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
05:13:31 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:31 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:31 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:31 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
05:13:31 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:31 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:32 PM     all     11.29      0.00      1.13      0.00      0.00     87.58
05:13:32 PM       0     86.00      0.00      5.00      0.00      0.00      9.00
05:13:32 PM       1      5.05      0.00      3.03      0.00      0.00     91.92
05:13:32 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
05:13:32 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:32 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:32 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:32 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
05:13:32 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:32 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:33 PM     all     11.65      0.00      1.00      0.00      0.00     87.34
05:13:33 PM       0     85.86      0.00      4.04      0.00      0.00     10.10
05:13:33 PM       1      6.06      0.00      3.03      0.00      0.00     90.91
05:13:33 PM       2      0.00      0.00      0.00      0.00      0.00    100.00
05:13:33 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:33 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:33 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:33 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
05:13:33 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:33 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:34 PM     all     11.57      0.00      0.88      0.00      0.00     87.55
05:13:34 PM       0     43.88      0.00      3.06      0.00      0.00     53.06
05:13:34 PM       1     50.00      0.00      4.00      0.00      0.00     46.00
05:13:34 PM       2      1.00      0.00      0.00      0.00      0.00     99.00
05:13:34 PM       3      0.00      0.00      0.00      0.00      0.00    100.00
05:13:34 PM       4      0.00      0.00      0.00      0.00      0.00    100.00
05:13:34 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:34 PM       6      0.00      0.00      0.00      0.00      0.00    100.00
05:13:34 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

05:13:34 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
05:13:35 PM     all      9.71      0.00      1.01      0.00      0.00     89.28
05:13:35 PM       0      6.19      0.00      3.09      0.00      0.00     90.72
05:13:35 PM       1     71.58      0.00      2.11      0.00      0.00     26.32
05:13:35 PM       2      2.02      0.00      0.00      0.00      0.00     97.98
05:13:35 PM       3      0.00      0.00      1.00      0.00      0.00     99.00
05:13:35 PM       4      0.00      0.00      0.99      0.00      0.00     99.01
05:13:35 PM       5      0.00      0.00      0.00      0.00      0.00    100.00
05:13:35 PM       6      0.00      0.00      1.00      0.00      0.00     99.00
05:13:35 PM       7      0.00      0.00      0.00      0.00      0.00    100.00

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all     11.28      0.00      1.05      0.01      0.00     87.66
Average:          0     34.27      0.00      3.83      0.00      0.00     61.89
Average:          1     56.05      0.00      3.70      0.00      0.00     40.25
Average:          2      0.56      0.00      0.22      0.11      0.00     99.11
Average:          3      0.00      0.00      0.11      0.00      0.00     99.89
Average:          4      0.00      0.00      0.11      0.00      0.00     99.89
Average:          5      0.00      0.00      0.00      0.00      0.00    100.00
Average:          6      0.00      0.00      0.56      0.00      0.00     99.44
Average:          7      0.00      0.00      0.00      0.00      0.00    100.00
  • Mroongaの方が%systemが高いが、他はそれほど差異がありません。

#62 Updated by Kenji Maruyama almost 4 years ago

"+livedoor +blog" が実環境で再現せず、仮想環境かつRPM版だけで再現する件について

プロファイリングしてみました。

[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 1
done: 3.76771593093872
[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 2
done: 33.1966350078583

perl plus_plus.pl 2 時のプロファイリング結果

[vagrant@localhost mrn_concurrent]$ opreport -l -m cpu, tid /usr/lib64/mysql/plugin/ha_mroonga.so.0.0.0
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
Processes with a thread ID of 11157
Processes with a thread ID of 11392
samples  %        samples  %        symbol name
29       41.4286  53       45.6897  ha_mroonga::storage_scan_time()
4         5.7143  0              0  ha_mroonga::check_count_skip(unsigned long, unsigned long, bool)
4         5.7143  3         2.5862  ha_mroonga::storage_info_variable_data_file_length()
3         4.2857  3         2.5862  ha_mroonga::generic_ft_init_ext_select(unsigned int, unsigned int, String*)
3         4.2857  2         1.7241  ha_mroonga::is_enable_optimization()
3         4.2857  0              0  mrn::ConditionConverter::~ConditionConverter()
2         2.8571  2         1.7241  ha_mroonga::check_fast_order_limit(_grn_table_sort_key**, int*, long long*)
2         2.8571  0              0  ha_mroonga::generic_ft_init()
2         2.8571  2         1.7241  ha_mroonga::storage_info(unsigned int)
2         2.8571  1         0.8621  mrn::ConditionConverter::find_match_against(Item const*)
2         2.8571  2         1.7241  mrn::ConditionConverter::is_convertable(Item const*)
1         1.4286  0              0  ha_mroonga::clear_empty_value_records()
1         1.4286  2         1.7241  ha_mroonga::extra(ha_extra_function)
1         1.4286  0              0  ha_mroonga::ft_init_ext(unsigned int, unsigned int, String*)
1         1.4286  1         0.8621  ha_mroonga::ft_read(unsigned char*)
1         1.4286  3         2.5862  ha_mroonga::generic_ft_init_ext_prepare_expression_in_boolean_mode(st_mrn_ft_info*, String*, _grn_obj*, _grn_obj*, _grn_obj*, _grn_obj*)
1         1.4286  3         2.5862  ha_mroonga::generic_reset()
1         1.4286  2         1.7241  ha_mroonga::reset()
1         1.4286  1         0.8621  ha_mroonga::storage_cond_push(Item const*)
1         1.4286  0              0  ha_mroonga::storage_extra(ha_extra_function)
1         1.4286  1         0.8621  ha_mroonga::storage_ft_init()
1         1.4286  0              0  ha_mroonga::storage_index_end()
1         1.4286  0              0  ha_mroonga::table_flags() const
1         1.4286  0              0  mrn::ConditionConverter::ConditionConverter(_grn_ctx*, _grn_obj*, bool)
1         1.4286  1         0.8621  mrn::encoding::set(_grn_ctx*, charset_info_st const*)
0              0  1         0.8621  ha_mroonga::clear_cursor_geo()
0              0  1         0.8621  ha_mroonga::clear_search_result_geo()
0              0  1         0.8621  ha_mroonga::cond_push(Item const*)
0              0  1         0.8621  ha_mroonga::external_lock(THD*, int)
0              0  2         1.7241  ha_mroonga::ft_init()
0              0  1         0.8621  ha_mroonga::generic_extra(ha_extra_function)
0              0  3         2.5862  ha_mroonga::generic_ft_init_ext(unsigned int, unsigned int, String*)
0              0  2         1.7241  ha_mroonga::index_init(unsigned int, bool)
0              0  1         0.8621  ha_mroonga::rebind_psi()
0              0  1         0.8621  ha_mroonga::scan_time()
0              0  1         0.8621  ha_mroonga::storage_external_lock(THD*, int)
0              0  1         0.8621  ha_mroonga::storage_ft_init_ext(unsigned int, unsigned int, String*)
0              0  1         0.8621  ha_mroonga::storage_index_init(unsigned int, bool)
0              0  2         1.7241  ha_mroonga::storage_info_variable()
0              0  1         0.8621  ha_mroonga::storage_lock_count() const
0              0  2         1.7241  ha_mroonga::storage_reset()
0              0  2         1.7241  ha_mroonga::storage_store_lock(THD*, st_thr_lock_data**, thr_lock_type)
0              0  1         0.8621  mrn::ConditionConverter::is_convertable(Item_func const*)
0              0  2         1.7241  mrn::MatchEscalationThresholdScope::~MatchEscalationThresholdScope()
0              0  3         2.5862  mrn_change_encoding
0              0  2         1.7241  mrn_clear_alter_share
0              0  2         1.7241  mrn_get_slot_data

perl plus_plus.pl 1 時のプロファイリング結果


[vagrant@localhost mrn_concurrent]$ opreport -l -m cpu, tid /usr/lib64/mysql/plugin/ha_mroonga.so.0.0.0
CPU: CPU with timer interrupt, speed 0 MHz (estimated)
Profiling through timer interrupt
samples  %        symbol name
8        23.5294  ha_mroonga::storage_scan_time()
3         8.8235  ha_mroonga::storage_info_variable_data_file_length()
2         5.8824  ha_mroonga::clear_cursor()
2         5.8824  ha_mroonga::generic_extra(ha_extra_function)
2         5.8824  ha_mroonga::generic_reset()
2         5.8824  mrn::ConditionConverter::is_convertable(Item const*)
1         2.9412  ha_mroonga::check_count_skip(unsigned long, unsigned long, bool)
1         2.9412  ha_mroonga::check_fast_order_limit(_grn_table_sort_key**, int*, long long*)
1         2.9412  ha_mroonga::clear_cursor_geo()
1         2.9412  ha_mroonga::extra(ha_extra_function)
1         2.9412  ha_mroonga::ft_read(unsigned char*)
1         2.9412  ha_mroonga::generic_ft_init_ext_prepare_expression_in_boolean_mode(st_mrn_ft_info*, String*, _grn_obj*, _grn_obj*, _grn_obj*, _grn_obj*)
1         2.9412  ha_mroonga::generic_ft_init_ext_select(unsigned int, unsigned int, String*)
1         2.9412  ha_mroonga::storage_cond_push(Item const*)
1         2.9412  ha_mroonga::storage_index_init(unsigned int, bool)
1         2.9412  ha_mroonga::storage_info(unsigned int)
1         2.9412  ha_mroonga::storage_lock_count() const
1         2.9412  ha_mroonga::storage_rebind_psi()
1         2.9412  ha_mroonga::storage_store_lock(THD*, st_thr_lock_data**, thr_lock_type)
1         2.9412  mrn::ConditionConverter::is_convertable(Item_func const*)
1         2.9412  mrn_clear_alter_share

[vagrant@localhost mrn_concurrent]$ perl plus_plus.pl 4 時のプロファイリング結果

done: 244.985782146454

samples  %        samples  %        samples  %        samples  %        symbol name
55       34.5912  64       36.9942  75       43.3526  78       44.0678  ha_mroonga::storage_scan_time()
8         5.0314  13        7.5145  12        6.9364  8         4.5198  ha_mroonga::generic_ft_init_ext_select(unsigned int, unsigned int, String*)
7         4.4025  4         2.3121  0              0  4         2.2599  ha_mroonga::generic_ft_init_ext(unsigned int, unsigned int, String*)
7         4.4025  3         1.7341  1         0.5780  5         2.8249  ha_mroonga::storage_info_variable_data_file_length()
6         3.7736  0              0  1         0.5780  4         2.2599  ha_mroonga::generic_reset()
5         3.1447  3         1.7341  4         2.3121  0              0  mrn_get_slot_data
4         2.5157  2         1.1561  5         2.8902  3         1.6949  ha_mroonga::is_enable_optimization()
4         2.5157  0              0  3         1.7341  1         0.5650  ha_mroonga::storage_external_lock(THD*, int)
4         2.5157  3         1.7341  2         1.1561  2         1.1299  ha_mroonga::storage_info(unsigned int)
4         2.5157  4         2.3121  2         1.1561  0              0  ha_mroonga::table_flags() const
3         1.8868  4         2.3121  1         0.5780  1         0.5650  ha_mroonga::generic_ft_init()
3         1.8868  4         2.3121  2         1.1561  3         1.6949  ha_mroonga::generic_ft_init_ext_prepare_expression_in_boolean_mode(st_mrn_ft_info*, String*, _grn_obj*, _grn_obj*, _grn_obj*, _grn_obj*)
3         1.8868  0              0  0              0  2         1.1299  mrn::ConditionConverter::is_convertable(Item const*)
3         1.8868  4         2.3121  3         1.7341  3         1.6949  mrn::ConditionConverter::is_convertable(Item_func const*)
3         1.8868  2         1.1561  2         1.1561  1         0.5650  mrn::MatchEscalationThresholdScope::MatchEscalationThresholdScope(_grn_ctx*, long long)
2         1.2579  2         1.1561  3         1.7341  2         1.1299  ha_mroonga::check_count_skip(unsigned long, unsigned long, bool)
2         1.2579  4         2.3121  2         1.1561  2         1.1299  ha_mroonga::check_fast_order_limit(_grn_table_sort_key**, int*, long long*)
2         1.2579  1         0.5780  3         1.7341  1         0.5650  ha_mroonga::external_lock(THD*, int)
2         1.2579  0              0  1         0.5780  0              0  ha_mroonga::index_end()
2         1.2579  3         1.7341  3         1.7341  2         1.1299  ha_mroonga::index_init(unsigned int, bool)
2         1.2579  0              0  1         0.5780  3         1.6949  ha_mroonga::info(unsigned int)
2         1.2579  0              0  2         1.1561  2         1.1299  ha_mroonga::storage_index_init(unsigned int, bool)
2         1.2579  3         1.7341  3         1.7341  2         1.1299  ha_mroonga::storage_lock_count() const
2         1.2579  1         0.5780  0              0  0              0  ha_mroonga::storage_reset()
2         1.2579  7         4.0462  3         1.7341  6         3.3898  mrn::encoding::set(_grn_ctx*, charset_info_st const*)
1         0.6289  0              0  0              0  2         1.1299  ha_mroonga::clear_cursor()
1         0.6289  0              0  1         0.5780  1         0.5650  ha_mroonga::clear_cursor_geo()
1         0.6289  0              0  1         0.5780  1         0.5650  ha_mroonga::ft_init()
1         0.6289  0              0  0              0  2         1.1299  ha_mroonga::generic_extra(ha_extra_function)
1         0.6289  3         1.7341  1         0.5780  2         1.1299  ha_mroonga::reset()
1         0.6289  0              0  2         1.1561  1         0.5650  ha_mroonga::scan_time()
1         0.6289  1         0.5780  1         0.5780  0              0  ha_mroonga::storage_cond_push(Item const*)
1         0.6289  0              0  0              0  1         0.5650  ha_mroonga::storage_extra(ha_extra_function)
1         0.6289  1         0.5780  1         0.5780  0              0  ha_mroonga::storage_ft_init_ext(unsigned int, unsigned int, String*)
1         0.6289  0              0  1         0.5780  1         0.5650  ha_mroonga::storage_ft_read(unsigned char*)
1         0.6289  1         0.5780  0              0  0              0  ha_mroonga::storage_info_variable()
1         0.6289  0              0  1         0.5780  2         1.1299  ha_mroonga::storage_info_variable_records()
1         0.6289  4         2.3121  3         1.7341  2         1.1299  ha_mroonga::storage_store_lock(THD*, st_thr_lock_data**, thr_lock_type)
1         0.6289  1         0.5780  3         1.7341  1         0.5650  ha_mroonga::storage_table_flags() const
1         0.6289  0              0  0              0  0              0  mrn::ConditionConverter::ConditionConverter(_grn_ctx*, _grn_obj*, bool)
1         0.6289  2         1.1561  1         0.5780  1         0.5650  mrn::ConditionConverter::find_match_against(Item const*)
1         0.6289  1         0.5780  0              0  2         1.1299  mrn::MatchEscalationThresholdScope::~MatchEscalationThresholdScope()
1         0.6289  3         1.7341  1         0.5780  2         1.1299  mrn_change_encoding
1         0.6289  2         1.1561  2         1.1561  2         1.1299  mrn_clear_alter_share
1         0.6289  0              0  0              0  1         0.5650  mrn_generic_ft_clear
0              0  1         0.5780  0              0  0              0  ha_mroonga::clear_empty_value_records()
0              0  0              0  0              0  1         0.5650  ha_mroonga::clear_search_result()
0              0  4         2.3121  2         1.1561  1         0.5650  ha_mroonga::clear_search_result_geo()
0              0  1         0.5780  3         1.7341  0              0  ha_mroonga::cond_push(Item const*)
0              0  1         0.5780  2         1.1561  1         0.5650  ha_mroonga::extra(ha_extra_function)
0              0  2         1.1561  1         0.5780  3         1.6949  ha_mroonga::file_size(char const*)
0              0  2         1.1561  2         1.1561  0              0  ha_mroonga::ft_init_ext(unsigned int, unsigned int, String*)
0              0  0              0  2         1.1561  1         0.5650  ha_mroonga::ft_read(unsigned char*)
0              0  4         2.3121  1         0.5780  3         1.6949  ha_mroonga::lock_count() const
0              0  1         0.5780  3         1.7341  3         1.6949  ha_mroonga::rebind_psi()
0              0  2         1.1561  0              0  1         0.5650  ha_mroonga::storage_ft_init()
0              0  1         0.5780  1         0.5780  0              0  ha_mroonga::storage_index_end()
0              0  0              0  1         0.5780  0              0  ha_mroonga::storage_rebind_psi()
0              0  0              0  1         0.5780  2         1.1299  ha_mroonga::store_lock(THD*, st_thr_lock_data**, thr_lock_type)
0              0  2         1.1561  1         0.5780  2         1.1299  mrn::ConditionConverter::~ConditionConverter()
0              0  2         1.1561  0              0  0              0  mrn_storage_ft_close_search

  • プロセス2, 1, 4の場合でプロファイリングしてみましたが、すべて、ha_mroonga::storage_scan_timeの割合が高いが、 プロセス数が2と4の場合とで比較すると、プロセス数4の場合でha_mroonga::storage_external_lockの割合が2に比べ高くなっているのが気になるところです。

#63 Updated by Kenji Maruyama almost 4 years ago

InnoDBでは再現していなくて、Mroongaでは再現しているので、InnoDBの方だけが何か並列実行に有利になるようなパラメーターを渡してMySQLレベルの最適化が聞いているんじゃないかと思うからです。

トレースログからInnoDBの最適化パラメータなかなか見つけられないでいますが、代わりに166 仮想環境 RPM版のInnoDBの設定パラメータの方を見てみました。

root@localhost mysql>show variables like 'innodb%';


+------------------------------------------+------------------------+
| Variable_name                            | Value                  |
+------------------------------------------+------------------------+
| innodb_adaptive_flushing                 | ON                     |
| innodb_adaptive_flushing_lwm             | 10                     |
| innodb_adaptive_hash_index               | ON                     |
| innodb_adaptive_max_sleep_delay          | 150000                 |
| innodb_additional_mem_pool_size          | 8388608                |
| innodb_api_bk_commit_interval            | 5                      |
| innodb_api_disable_rowlock               | OFF                    |
| innodb_api_enable_binlog                 | OFF                    |
| innodb_api_enable_mdl                    | OFF                    |
| innodb_api_trx_level                     | 0                      |
| innodb_autoextend_increment              | 64                     |
| innodb_autoinc_lock_mode                 | 1                      |
| innodb_buffer_pool_dump_at_shutdown      | ON                     |
| innodb_buffer_pool_dump_now              | OFF                    |
| innodb_buffer_pool_filename              | ib_buffer_pool         |
| innodb_buffer_pool_instances             | 1                      |
| innodb_buffer_pool_load_abort            | OFF                    |
| innodb_buffer_pool_load_at_startup       | ON                     |
| innodb_buffer_pool_load_now              | OFF                    |
| innodb_buffer_pool_size                  | 1073741824             |
| innodb_change_buffer_max_size            | 25                     |
| innodb_change_buffering                  | all                    |
| innodb_checksum_algorithm                | crc32                  |
| innodb_checksums                         | ON                     |
| innodb_cmp_per_index_enabled             | OFF                    |
| innodb_commit_concurrency                | 0                      |
| innodb_compression_failure_threshold_pct | 5                      |
| innodb_compression_level                 | 6                      |
| innodb_compression_pad_pct_max           | 50                     |
| innodb_concurrency_tickets               | 5000                   |
| innodb_data_file_path                    | ibdata1:10M:autoextend |
| innodb_data_home_dir                     | /var/lib/mysql         |
| innodb_disable_sort_file_cache           | OFF                    |
| innodb_doublewrite                       | ON                     |
| innodb_fast_shutdown                     | 1                      |
| innodb_file_format                       | Barracuda              |
| innodb_file_format_check                 | ON                     |
| innodb_file_format_max                   | Antelope               |
| innodb_file_per_table                    | ON                     |
| innodb_flush_log_at_timeout              | 1                      |
| innodb_flush_log_at_trx_commit           | 1                      |
| innodb_flush_method                      | O_DIRECT               |
| innodb_flush_neighbors                   | 1                      |
| innodb_flushing_avg_loops                | 30                     |
| innodb_force_load_corrupted              | OFF                    |
| innodb_force_recovery                    | 0                      |
| innodb_ft_aux_table                      |                        |
| innodb_ft_cache_size                     | 8000000                |
| innodb_ft_enable_diag_print              | OFF                    |
| innodb_ft_enable_stopword                | ON                     |
| innodb_ft_max_token_size                 | 84                     |
| innodb_ft_min_token_size                 | 3                      |
| innodb_ft_num_word_optimize              | 2000                   |
| innodb_ft_result_cache_limit             | 2000000000             |
| innodb_ft_server_stopword_table          |                        |
| innodb_ft_sort_pll_degree                | 2                      |
| innodb_ft_total_cache_size               | 640000000              |
| innodb_ft_user_stopword_table            |                        |
| innodb_io_capacity                       | 400                    |
| innodb_io_capacity_max                   | 2000                   |
| innodb_large_prefix                      | ON                     |
| innodb_lock_wait_timeout                 | 120                    |
| innodb_locks_unsafe_for_binlog           | OFF                    |
| innodb_log_buffer_size                   | 16777216               |
| innodb_log_compressed_pages              | ON                     |
| innodb_log_file_size                     | 134217728              |
| innodb_log_files_in_group                | 2                      |
| innodb_log_group_home_dir                | ./                     |
| innodb_lru_scan_depth                    | 1024                   |
| innodb_max_dirty_pages_pct               | 75                     |
| innodb_max_dirty_pages_pct_lwm           | 0                      |
| innodb_max_purge_lag                     | 0                      |
| innodb_max_purge_lag_delay               | 0                      |
| innodb_mirrored_log_groups               | 1                      |
| innodb_monitor_disable                   |                        |
| innodb_monitor_enable                    |                        |
| innodb_monitor_reset                     |                        |
| innodb_monitor_reset_all                 |                        |
| innodb_old_blocks_pct                    | 37                     |
| innodb_old_blocks_time                   | 1000                   |
| innodb_online_alter_log_max_size         | 134217728              |
| innodb_open_files                        | 300                    |
| innodb_optimize_fulltext_only            | OFF                    |
| innodb_page_size                         | 16384                  |
| innodb_print_all_deadlocks               | ON                     |
| innodb_purge_batch_size                  | 300                    |
| innodb_purge_threads                     | 1                      |
| innodb_random_read_ahead                 | OFF                    |
| innodb_read_ahead_threshold              | 56                     |
| innodb_read_io_threads                   | 8                      |
| innodb_read_only                         | OFF                    |
| innodb_replication_delay                 | 0                      |
| innodb_rollback_on_timeout               | OFF                    |
| innodb_rollback_segments                 | 128                    |
| innodb_sort_buffer_size                  | 1048576                |
| innodb_spin_wait_delay                   | 6                      |
| innodb_stats_auto_recalc                 | ON                     |
| innodb_stats_method                      | nulls_equal            |
| innodb_stats_on_metadata                 | OFF                    |
| innodb_stats_persistent                  | ON                     |
| innodb_stats_persistent_sample_pages     | 20                     |
| innodb_stats_sample_pages                | 8                      |
| innodb_stats_transient_sample_pages      | 8                      |
| innodb_strict_mode                       | ON                     |
| innodb_support_xa                        | ON                     |
| innodb_sync_array_size                   | 1                      |
| innodb_sync_spin_loops                   | 30                     |
| innodb_table_locks                       | ON                     |
| innodb_thread_concurrency                | 0                      |
| innodb_thread_sleep_delay                | 10000                  |
| innodb_undo_directory                    | .                      |
| innodb_undo_logs                         | 128                    |
| innodb_undo_tablespaces                  | 0                      |
| innodb_use_native_aio                    | ON                     |
| innodb_use_sys_malloc                    | ON                     |
| innodb_version                           | 5.6.15                 |
| innodb_write_io_threads                  | 8                      |
+------------------------------------------+------------------------+
117 rows in set (0.00 sec)

RPM版はカスタマイズされたmy.cnfを使っているので、rpmから抽出したデフォルトのmy.cnfによるパラメータは以下になります。

mysql> show variables like 'innodb%';
+------------------------------------------+------------------------+
| Variable_name                            | Value                  |
+------------------------------------------+------------------------+
| innodb_adaptive_flushing                 | ON                     |
| innodb_adaptive_flushing_lwm             | 10                     |
| innodb_adaptive_hash_index               | ON                     |
| innodb_adaptive_max_sleep_delay          | 150000                 |
| innodb_additional_mem_pool_size          | 8388608                |
| innodb_api_bk_commit_interval            | 5                      |
| innodb_api_disable_rowlock               | OFF                    |
| innodb_api_enable_binlog                 | OFF                    |
| innodb_api_enable_mdl                    | OFF                    |
| innodb_api_trx_level                     | 0                      |
| innodb_autoextend_increment              | 64                     |
| innodb_autoinc_lock_mode                 | 1                      |
| innodb_buffer_pool_dump_at_shutdown      | OFF                    |
| innodb_buffer_pool_dump_now              | OFF                    |
| innodb_buffer_pool_filename              | ib_buffer_pool         |
| innodb_buffer_pool_instances             | 8                      |
| innodb_buffer_pool_load_abort            | OFF                    |
| innodb_buffer_pool_load_at_startup       | OFF                    |
| innodb_buffer_pool_load_now              | OFF                    |
| innodb_buffer_pool_size                  | 134217728              |
| innodb_change_buffer_max_size            | 25                     |
| innodb_change_buffering                  | all                    |
| innodb_checksum_algorithm                | innodb                 |
| innodb_checksums                         | ON                     |
| innodb_cmp_per_index_enabled             | OFF                    |
| innodb_commit_concurrency                | 0                      |
| innodb_compression_failure_threshold_pct | 5                      |
| innodb_compression_level                 | 6                      |
| innodb_compression_pad_pct_max           | 50                     |
| innodb_concurrency_tickets               | 5000                   |
| innodb_data_file_path                    | ibdata1:12M:autoextend |
| innodb_data_home_dir                     |                        |
| innodb_disable_sort_file_cache           | OFF                    |
| innodb_doublewrite                       | ON                     |
| innodb_fast_shutdown                     | 1                      |
| innodb_file_format                       | Antelope               |
| innodb_file_format_check                 | ON                     |
| innodb_file_format_max                   | Antelope               |
| innodb_file_per_table                    | ON                     |
| innodb_flush_log_at_timeout              | 1                      |
| innodb_flush_log_at_trx_commit           | 1                      |
| innodb_flush_method                      |                        |
| innodb_flush_neighbors                   | 1                      |
| innodb_flushing_avg_loops                | 30                     |
| innodb_force_load_corrupted              | OFF                    |
| innodb_force_recovery                    | 0                      |
| innodb_ft_aux_table                      |                        |
| innodb_ft_cache_size                     | 8000000                |
| innodb_ft_enable_diag_print              | OFF                    |
| innodb_ft_enable_stopword                | ON                     |
| innodb_ft_max_token_size                 | 84                     |
| innodb_ft_min_token_size                 | 3                      |
| innodb_ft_num_word_optimize              | 2000                   |
| innodb_ft_result_cache_limit             | 2000000000             |
| innodb_ft_server_stopword_table          |                        |
| innodb_ft_sort_pll_degree                | 2                      |
| innodb_ft_total_cache_size               | 640000000              |
| innodb_ft_user_stopword_table            |                        |
| innodb_io_capacity                       | 200                    |
| innodb_io_capacity_max                   | 2000                   |
| innodb_large_prefix                      | OFF                    |
| innodb_lock_wait_timeout                 | 50                     |
| innodb_locks_unsafe_for_binlog           | OFF                    |
| innodb_log_buffer_size                   | 8388608                |
| innodb_log_compressed_pages              | ON                     |
| innodb_log_file_size                     | 50331648               |
| innodb_log_files_in_group                | 2                      |
| innodb_log_group_home_dir                | ./                     |
| innodb_lru_scan_depth                    | 1024                   |
| innodb_max_dirty_pages_pct               | 75                     |
| innodb_max_dirty_pages_pct_lwm           | 0                      |
| innodb_max_purge_lag                     | 0                      |
| innodb_max_purge_lag_delay               | 0                      |
| innodb_mirrored_log_groups               | 1                      |
| innodb_monitor_disable                   |                        |
| innodb_monitor_enable                    |                        |
| innodb_monitor_reset                     |                        |
| innodb_monitor_reset_all                 |                        |
| innodb_old_blocks_pct                    | 37                     |
| innodb_old_blocks_time                   | 1000                   |
| innodb_online_alter_log_max_size         | 134217728              |
| innodb_open_files                        | 2000                   |
| innodb_optimize_fulltext_only            | OFF                    |
| innodb_page_size                         | 16384                  |
| innodb_print_all_deadlocks               | OFF                    |
| innodb_purge_batch_size                  | 300                    |
| innodb_purge_threads                     | 1                      |
| innodb_random_read_ahead                 | OFF                    |
| innodb_read_ahead_threshold              | 56                     |
| innodb_read_io_threads                   | 4                      |
| innodb_read_only                         | OFF                    |
| innodb_replication_delay                 | 0                      |
| innodb_rollback_on_timeout               | OFF                    |
| innodb_rollback_segments                 | 128                    |
| innodb_sort_buffer_size                  | 1048576                |
| innodb_spin_wait_delay                   | 6                      |
| innodb_stats_auto_recalc                 | ON                     |
| innodb_stats_method                      | nulls_equal            |
| innodb_stats_on_metadata                 | OFF                    |
| innodb_stats_persistent                  | ON                     |
| innodb_stats_persistent_sample_pages     | 20                     |
| innodb_stats_sample_pages                | 8                      |
| innodb_stats_transient_sample_pages      | 8                      |
| innodb_strict_mode                       | OFF                    |
| innodb_support_xa                        | ON                     |
| innodb_sync_array_size                   | 1                      |
| innodb_sync_spin_loops                   | 30                     |
| innodb_table_locks                       | ON                     |
| innodb_thread_concurrency                | 0                      |
| innodb_thread_sleep_delay                | 10000                  |
| innodb_undo_directory                    | .                      |
| innodb_undo_logs                         | 128                    |
| innodb_undo_tablespaces                  | 0                      |
| innodb_use_native_aio                    | ON                     |
| innodb_use_sys_malloc                    | ON                     |
| innodb_version                           | 5.6.15                 |
| innodb_write_io_threads                  | 4                      |
+------------------------------------------+------------------------+
117 rows in set (0.00 sec)

  • 全文検索に関係ありそうな設定を抽出

root@localhost mysql>show variables like 'innodb_ft%';
+---------------------------------+------------+
| Variable_name                   | Value      |
+---------------------------------+------------+
| innodb_ft_aux_table             |            |
| innodb_ft_cache_size            | 8000000    |
| innodb_ft_enable_diag_print     | OFF        |
| innodb_ft_enable_stopword       | ON         |
| innodb_ft_max_token_size        | 84         |
| innodb_ft_min_token_size        | 3          |
| innodb_ft_num_word_optimize     | 2000       |
| innodb_ft_result_cache_limit    | 2000000000 |
| innodb_ft_server_stopword_table |            |
| innodb_ft_sort_pll_degree       | 2          |
| innodb_ft_total_cache_size      | 640000000  |
| innodb_ft_user_stopword_table   |            |
+---------------------------------+------------+
12 rows in set (0.00 sec)

上記のinnodb_ft_result_cache_limit, innodb_ft_total_cache_size、それとinnodb_buffer_pool_sizeがきになるところです。同じ問い合わせの繰り返しなのでSQL_NOCACHEになっていても、ストレージエンジン内部のキャッシュが効いている気がします。毎回異なるクエリーでInnoDBで再現するか検証してみます。

参照:

http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_ft_cache_size

https://dev.mysql.com/doc/refman/5.5/en/innodb-buffer-pool.html

http://stackoverflow.com/questions/6666631/sql-no-cache-does-not-work

#64 Updated by Kenji Maruyama almost 4 years ago

毎回異なるクエリーでInnoDBで再現するか検証してみます。

手順

元データから特徴語抽出して検索ワードとする

Mecab で"名詞,固有名詞"だけを抽出

mecab blog30.sql -b 10000000 | grep "名詞,固有名詞" | cut -f 1 | sort | uniq -c | sort -r -n > res.out

先頭のスペース削除
sed -e 's/^  *//g' res.out > res2.out

単語だけ切り出す
cat res2.out | cut -d' ' -f2 > res3.out

ランダムに4つ単語抽出して、perlの配列の一つの要素とする。(1000要素合成)
awk '{l[NR]=$0} END{srand(seed); n=0; while(n<1000) { print "\047" l[int((rand()*NR))+1] " " l[int((rand()*NR))+1] " " l[int((rand()*NR))+1] " " l[int((rand()*NR))+1] "\047"; n++
} }' res3.out >> result.out

実行スクリプトは以下です。1000件のキーワードに対して333件ランダムに選び検索する

#!/usr/bin/perl

use DBI;
use Time::HiRes;
use List::Util qw/shuffle/;
$|=1;

my $p = $ARGV[0] || 1;

my @data = (

'THE TECHNO 野村 横浜市大',
'Yahoo livedoorID 中日 中日',
'DVD livedoorBlog 清美 No',
'毎日 AM 民生 九州',

中略... 

'ZEPP 英行 TECHNO PATISSIOLLE',
'アテネ 聡 ラウール・ゴンザレス Web',
'HIPHOP S TENDER 麻耶',
'プロバイダ 弘樹 漢 荻野',
'桜井 iPod YouTube KEY'
);

my $t2 = Time::HiRes::time;
for (1..$p) {
    fork and next;
    srand();
    my $dbh = DBI->connect("dbi:mysql:article_index;hostname=localhost;mysql_socket=/home/mmmaru777/mysql/mroonga/m
ysql.sock","root","",{mysql_enable_utf8=>1});
      for (1..333) {
        my $l = shuffle(@data);
        $l =~ s!([\(\)~\+><\-*])!\\$1!g;
        my $t = Time::HiRes::time;
        my $key = "article_index_0099";
        #$dbh->selectrow_arrayref('SELECT GET_LOCK(?,30)', {}, $key);
        my $sth = $dbh->prepare(<<"SQL");
SELECT SQL_NO_CACHE article_id FROM article_index_0099 WHERE MATCH(public_terms) AGAINST(CONCAT_WS(" ","+(",?,")")
IN BOOLEAN MODE);
SQL
        $sth->execute($l);
        $sth->finish;
        #$dbh->selectrow_arrayref('SELECT RELEASE_LOCK(?)', {}, $key);
        my $e = Time::HiRes::time - $t;
        # print "[$$] slow $e\n" if $e > 3;
    }
    exit;
}

while ( waitpid( -1, 0) >= 0 ) {};
my $e2 = Time::HiRes::time - $t2;
print "done: $e2\n";

  • 実行結果

参考までにMroongaは以下になります。

Mroonga

mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 1
done: 1.21622705459595
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 2
done: 2.09424781799316
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 3
done: 2.9491081237793
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 4
done: 4.74567890167236
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 5
done: 4.68890595436096
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 6
done: 5.40417289733887
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 7
done: 6.44782114028931
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 8
done: 6.85385704040527

InnoDBは以下になります。

mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 1
done: 1.72052478790283
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 2
done: 2.48369407653809
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 3
done: 1.89162802696228
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 4
done: 1.83174800872803
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 5
done: 1.90698504447937
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 6
done: 2.01898407936096
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 7
done: 2.16546392440796
mmmaru777@s37:~/mrn_bugs/2335$ perl rnd_bench_simple.pl 8
done: 2.43259787559509
  • 結果をみると、InnoDBはランダムでも性能が悪化することはなさそうです。

#65 Updated by Kenji Maruyama almost 4 years ago

perl bench.pl 8 でMySQLDのシステムコールの実行時間を測ってみました。(クエリは何も加工していない元のクエリです)

Mroonga 

vagrant@localhost ~]$ sudo strace -c -p 8255
Process 8255 attached - interrupt to quit
^CProcess 8255 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 60.66    0.008999        8999         1           restart_syscall
 15.37    0.002281         326         7           poll
 11.06    0.001641         103        16           futex
  7.62    0.001130          47        24           fcntl
  3.08    0.000457          57         8           accept
  2.21    0.000328          41         8         8 setsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.014836                    64         8 total

InnoDB

[vagrant@localhost ~]$
[vagrant@localhost ~]$ sudo strace -c -p 8255
Process 8255 attached - interrupt to quit
^CProcess 8255 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 96.26    0.007999        7999         1           restart_syscall
  2.84    0.000236          10        24           fcntl
  0.90    0.000075          11         7           poll
  0.00    0.000000           0         8           accept
  0.00    0.000000           0         8         8 setsockopt
  0.00    0.000000           0        14           futex
------ ----------- ----------- --------- --------- ----------------
100.00    0.008310                    62         8 total

perl bench.pl 1時の Mroonga

[vagrant@localhost ~]$ sudo strace -c -p 8255
Process 8255 attached - interrupt to quit
^CProcess 8255 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.007999        7999         1           restart_syscall
  0.00    0.000000           0         1           accept
  0.00    0.000000           0         1         1 setsockopt
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         2           futex
------ ----------- ----------- --------- --------- ----------------
100.00    0.007999                     8         1 total
  • 結果より、Mroongaは8プロセス時には120秒ほどかかるので、futexのシステムコールの影響は微々たるものです。

  • Mroongaに複数プロセス接続のクライアント側で複数プロセスに対して同時にstraceを使ってアタッチして見たところ、lockによってどれが途中で待ち状態になっていることも確認できなかったです。

#66 Updated by Kouhei Sutou almost 4 years ago

ちょっと仮想マシンにおじゃまして試してみました。

SELECT SQL_NO_CACHE article_id FROM article_index_0099 LIMIT 0;

だと再現しなくて、

SELECT SQL_NO_CACHE article_id FROM article_index_0099 LIMIT 1;

だと再現しますね。

実環境でも

SELECT SQL_NO_CACHE article_id FROM article_index_0099 LIMIT 500;

くらいにすると再現します。(実環境ではLIMIT 1くらいでは再現しません。)

ということは、MySQLとMroongaの間で渡すデータの量が関係していると考えられます。

実環境でLIMIT 500のSQLを一回トレースログをとるとMroongaのどこでMySQL用のデータを格納しているかわかります。その処理の中の一部を定数にしたり、処理自体をコメントアウトしながら計測していけば、どこが原因か絞り込める気がします。

Groongaを直接使ったときは発生していないということなので、個人的には次のどれかじゃないかなぁとは思いますが。。。

  • どっかでメモリーをアロケートしている
  • メモリー上のデータのコピーが重い
  • どっかでI/Oが走ってしまっている

#67 Updated by Kenji Maruyama almost 4 years ago

mysqldは接続を確立するとcloneして子スレッドにその後の処理を任せますので、straceに-fを付けないと接続を待ち受けているmainスレッドの情報しか見られていないかと。。

ありがとうございます! yoku0825さん.

http://redmine.groonga.org/issues/2335#note-65 再計測しました。

InnoDB (プロセス数1)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.35    3.883403        1172      3314           io_getevents
 19.14    1.041701        2175       479       237 futex
  7.66    0.416936        2278       183           select
  1.67    0.090988       15165         6         5 restart_syscall
  0.17    0.009381           1     11884           gettimeofday
  0.00    0.000271          68         4           lseek
  0.00    0.000000           0         5           read
  0.00    0.000000           0         1           open
  0.00    0.000000           0         2           close
  0.00    0.000000           0        81           poll
  0.00    0.000000           0         2           pread
  0.00    0.000000           0        25           pwrite
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         2           sched_yield
  0.00    0.000000           0         1           accept
  0.00    0.000000           0      1003           sendto
  0.00    0.000000           0      2087        81 recvfrom
  0.00    0.000000           0         1           shutdown
  0.00    0.000000           0         2         1 setsockopt
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0        27           fsync
  0.00    0.000000           0         2           io_submit
  0.00    0.000000           0      1000           clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00    5.442680                 20116       325 total


Mroonga (プロセス数1)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.60  108.452515       22566      4806           io_getevents
 19.68   29.804537       44484       670       331 futex
  7.91   11.984169       44717       268           select
  0.23    0.345945       57658         6         5 restart_syscall
  0.15    0.229198          19     12000           mmap
  0.13    0.196552          16     12000           munmap
  0.10    0.156752          17      9000           stat
  0.10    0.148983          17      9000           clock_gettime
  0.05    0.074598          18      4241           gettimeofday
  0.02    0.035912          36      1003           sendto
  0.02    0.028838          13      2178       172 recvfrom
  0.01    0.012261          71       172           poll
  0.00    0.000394         394         1           accept
  0.00    0.000000           0         1           close
  0.00    0.000000           0         1           access
  0.00    0.000000           0         1           shutdown
  0.00    0.000000           0         2         1 setsockopt
  0.00    0.000000           0         3           fcntl
------ ----------- ----------- --------- --------- ----------------
100.00  151.470654                 55353       509 total

InnoDB (プロセス数8)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 68.22  246.043607      111991      2197           io_getevents
 19.92   71.828813        3418     21012      5280 futex
  7.51   27.092885      223908       121           select
  1.97    7.097858          61    117089           gettimeofday
  1.01    3.643096          78     47006           sched_yield
  0.47    1.710554         244      7000           madvise
  0.27    0.977243          53     18408      2360 recvfrom
  0.25    0.886351      147725         6         5 restart_syscall
  0.14    0.516884          65      8000           clock_gettime
  0.13    0.486274          61      8024           sendto
  0.05    0.189541        4408        43           fsync
  0.05    0.184147          78      2367           poll
  0.00    0.002942          72        41           pwrite
  0.00    0.000529          66         8           access
  0.00    0.000515          64         8           accept
  0.00    0.000337          14        24           fcntl
  0.00    0.000056           4        16         8 setsockopt
  0.00    0.000000           0         8           close
  0.00    0.000000           0         8           shutdown
  0.00    0.000000           0         2           io_submit
------ ----------- ----------- --------- --------- ----------------
100.00  360.661632                231388      7653 total

Mroonga (プロセス数8)

[vagrant@localhost ~]$ sudo strace -c -f -p 5848

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.09 2290.630877      457760      5004           io_getevents
 19.41  683.007120        3857    177081     45368 futex
  7.24  254.727918      916287       278           select
  3.97  139.742238        1456     96003           munmap
  2.46   86.732168         903     96051           mmap
  0.58   20.544093         285     72000           clock_gettime
  0.46   16.158940         224     72000           stat
  0.21    7.465583        1068      6993           madvise
  0.17    6.064860         239     25337           gettimeofday
  0.14    4.804270      800712         6         5 restart_syscall
  0.13    4.598821         228     20147      4099 recvfrom
  0.08    2.854554         356      8024           sendto
  0.06    1.947352         474      4106           poll
  0.00    0.002087         232         9           close
  0.00    0.000000           0         5           read
  0.00    0.000000           0         1           open
  0.00    0.000000           0         4           lseek
  0.00    0.000000           0         2           pread
  0.00    0.000000           0        16         8 access
  0.00    0.000000           0         8           accept
  0.00    0.000000           0         8           shutdown
  0.00    0.000000           0        16         8 setsockopt
  0.00    0.000000           0        24           fcntl
------ ----------- ----------- --------- --------- ----------------
100.00 3519.280881                583123     49488 total

secondsが実測値を大きく超えているのはmysqldのすべてのスレッドの合計値をとっているからかと思います。

syscallの%timeをみると、InnoDBとMroongaとでそれほど差異はない。

secondsでみると、プロセス数1の場合でもMroongaはInnoDBに比べ、io_getevnets,futex,selectに数十倍以上時間かかっているが、 プロセス数8のときは10倍ほど時間がかかっている。

MroongaはI/O周りが重いことが読み取れます。

#68 Updated by Kenji Maruyama almost 4 years ago

MySQLとMroongaの間で渡すデータの量が関係していると考えられます。
実環境でLIMIT 500のSQLを一回トレースログをとるとMroongaのどこでMySQL用のデータを格納しているかわかります。その処理の中の一部を定数にしたり、処理自体をコメントアウトしながら計測していけば、どこが原因か絞り込める気がします。

ありがとうございます。試してみます。

どっかでI/Oが走ってしまっている

straceの結果をみるとこれのような気がします。

#69 Updated by Kenji Maruyama almost 4 years ago

仮想環境で Groonga Server ( http://redmine.groonga.org/issues/2335#note-21 ) の CPU使用率を計測してみました。

プロセス数1の場合とプロセス数8の場合になります。

groonga -d /var/lib/mysql/article_index.mrn -t 1 --cache-limit 0
perl bench_grn_gqtp.pl 1

sar -P ALL 1 15

[root@localhost vagrant]# sar -P ALL 1 15
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/07/2014  _x86_64_    (8 CPU)

01:13:45 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:46 AM     all      5.40      0.00      8.30      0.00      0.00     86.30
01:13:46 AM       0      3.37      0.00     13.48      0.00      0.00     83.15
01:13:46 AM       1      2.25      0.00     12.36      0.00      0.00     85.39
01:13:46 AM       2      1.04      0.00      1.04      0.00      0.00     97.92
01:13:46 AM       3     10.42      0.00     10.42      0.00      0.00     79.17
01:13:46 AM       4      5.15      0.00      4.12      0.00      0.00     90.72
01:13:46 AM       5     14.89      0.00     21.28      0.00      0.00     63.83
01:13:46 AM       6      6.19      0.00      5.15      0.00      0.00     88.66
01:13:46 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:46 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:47 AM     all      4.76      0.00      8.86      0.00      0.00     86.38
01:13:47 AM       0      3.37      0.00     13.48      0.00      0.00     83.15
01:13:47 AM       1      2.20      0.00     10.99      0.00      0.00     86.81
01:13:47 AM       2      1.03      0.00      4.12      0.00      0.00     94.85
01:13:47 AM       3      8.51      0.00     10.64      0.00      0.00     80.85
01:13:47 AM       4      3.06      0.00      5.10      0.00      0.00     91.84
01:13:47 AM       5     15.05      0.00     22.58      0.00      0.00     62.37
01:13:47 AM       6      4.17      0.00      6.25      0.00      0.00     89.58
01:13:47 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:47 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:48 AM     all      4.57      0.00      8.88      0.00      0.00     86.55
01:13:48 AM       0      3.37      0.00     13.48      0.00      0.00     83.15
01:13:48 AM       1      1.11      0.00     12.22      0.00      0.00     86.67
01:13:48 AM       2      0.00      0.00      1.03      0.00      0.00     98.97
01:13:48 AM       3     12.50      0.00     10.42      0.00      0.00     77.08
01:13:48 AM       4      2.00      0.00      3.00      0.00      0.00     95.00
01:13:48 AM       5     18.95      0.00     30.53      0.00      0.00     50.53
01:13:48 AM       6      1.00      0.00      3.00      0.00      0.00     96.00
01:13:48 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:48 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:49 AM     all      4.93      0.00      8.39      0.00      0.00     86.68
01:13:49 AM       0      2.33      0.00      8.14      0.00      0.00     89.53
01:13:49 AM       1      0.00      0.00      7.95      0.00      0.00     92.05
01:13:49 AM       2      1.09      0.00      8.70      0.00      0.00     90.22
01:13:49 AM       3     13.83      0.00     11.70      0.00      0.00     74.47
01:13:49 AM       4      1.03      0.00      2.06      0.00      0.00     96.91
01:13:49 AM       5     17.58      0.00     25.27      0.00      0.00     57.14
01:13:49 AM       6      1.02      0.00      2.04      0.00      0.00     96.94
01:13:49 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:49 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:50 AM     all      4.78      0.00      8.63      0.00      0.00     86.59
01:13:50 AM       0      4.71      0.00     14.12      0.00      0.00     81.18
01:13:50 AM       1      1.10      0.00      4.40      0.00      0.00     94.51
01:13:50 AM       2      2.15      0.00      8.60      0.00      0.00     89.25
01:13:50 AM       3     10.87      0.00     13.04      0.00      0.00     76.09
01:13:50 AM       4      1.01      0.00      2.02      0.00      0.00     96.97
01:13:50 AM       5     20.21      0.00     27.66      0.00      0.00     52.13
01:13:50 AM       6      1.00      0.00      1.00      0.00      0.00     98.00
01:13:50 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:50 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:51 AM     all      4.67      0.00      8.95      0.00      0.00     86.38
01:13:51 AM       0      3.49      0.00     16.28      0.00      0.00     80.23
01:13:51 AM       1      1.14      0.00      7.95      0.00      0.00     90.91
01:13:51 AM       2      1.09      0.00      6.52      0.00      0.00     92.39
01:13:51 AM       3     11.58      0.00     12.63      0.00      0.00     75.79
01:13:51 AM       4      3.06      0.00      5.10      0.00      0.00     91.84
01:13:51 AM       5     15.05      0.00     21.51      0.00      0.00     63.44
01:13:51 AM       6      1.03      0.00      3.09      0.00      0.00     95.88
01:13:51 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:51 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:52 AM     all      4.72      0.00      8.91      0.00      0.00     86.37
01:13:52 AM       0      3.33      0.00     14.44      0.00      0.00     82.22
01:13:52 AM       1      2.25      0.00     11.24      0.00      0.00     86.52
01:13:52 AM       2      1.01      0.00      4.04      0.00      0.00     94.95
01:13:52 AM       3     11.58      0.00     10.53      0.00      0.00     77.89
01:13:52 AM       4      3.09      0.00      2.06      0.00      0.00     94.85
01:13:52 AM       5     14.89      0.00     26.60      0.00      0.00     58.51
01:13:52 AM       6      2.04      0.00      4.08      0.00      0.00     93.88
01:13:52 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:52 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:53 AM     all      5.02      0.00      8.59      0.00      0.00     86.39
01:13:53 AM       0      2.33      0.00     12.79      0.00      0.00     84.88
01:13:53 AM       1      2.25      0.00     11.24      0.00      0.00     86.52
01:13:53 AM       2      2.06      0.00      3.09      0.00      0.00     94.85
01:13:53 AM       3      9.47      0.00      9.47      0.00      0.00     81.05
01:13:53 AM       4      6.12      0.00      6.12      0.00      0.00     87.76
01:13:53 AM       5     12.63      0.00     18.95      0.00      0.00     68.42
01:13:53 AM       6      5.05      0.00      9.09      0.00      0.00     85.86
01:13:53 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:53 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:54 AM     all      4.87      0.00      8.56      0.00      0.00     86.56
01:13:54 AM       0      3.33      0.00     15.56      0.00      0.00     81.11
01:13:54 AM       1      1.14      0.00     10.23      0.00      0.00     88.64
01:13:54 AM       2      1.05      0.00      3.16      0.00      0.00     95.79
01:13:54 AM       3     12.63      0.00     10.53      0.00      0.00     76.84
01:13:54 AM       4      3.06      0.00      4.08      0.00      0.00     92.86
01:13:54 AM       5     17.02      0.00     22.34      0.00      0.00     60.64
01:13:54 AM       6      1.02      0.00      3.06      0.00      0.00     95.92
01:13:54 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:54 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:55 AM     all      4.77      0.00      8.61      0.00      0.00     86.62
01:13:55 AM       0      2.30      0.00      9.20      0.00      0.00     88.51
01:13:55 AM       1      2.25      0.00     12.36      0.00      0.00     85.39
01:13:55 AM       2      3.12      0.00      6.25      0.00      0.00     90.62
01:13:55 AM       3     10.42      0.00     12.50      0.00      0.00     77.08
01:13:55 AM       4      4.12      0.00      5.15      0.00      0.00     90.72
01:13:55 AM       5     15.05      0.00     21.51      0.00      0.00     63.44
01:13:55 AM       6      1.01      0.00      4.04      0.00      0.00     94.95
01:13:55 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:55 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:56 AM     all      4.60      0.00      8.94      0.00      0.00     86.47
01:13:56 AM       0      3.33      0.00     11.11      0.00      0.00     85.56
01:13:56 AM       1      1.12      0.00     12.36      0.00      0.00     86.52
01:13:56 AM       2      2.06      0.00      4.12      0.00      0.00     93.81
01:13:56 AM       3     11.46      0.00     12.50      0.00      0.00     76.04
01:13:56 AM       4      3.03      0.00      3.03      0.00      0.00     93.94
01:13:56 AM       5     16.13      0.00     29.03      0.00      0.00     54.84
01:13:56 AM       6      1.01      0.00      2.02      0.00      0.00     96.97
01:13:56 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:56 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:57 AM     all      4.78      0.00      9.03      0.00      0.00     86.19
01:13:57 AM       0      3.45      0.00     10.34      0.00      0.00     86.21
01:13:57 AM       1      3.41      0.00     10.23      0.00      0.00     86.36
01:13:57 AM       2      4.21      0.00     11.58      0.00      0.00     84.21
01:13:57 AM       3      7.37      0.00      9.47      0.00      0.00     83.16
01:13:57 AM       4      6.32      0.00      8.42      0.00      0.00     85.26
01:13:57 AM       5     10.53      0.00     16.84      0.00      0.00     72.63
01:13:57 AM       6      4.08      0.00      5.10      0.00      0.00     90.82
01:13:57 AM       7      0.00      0.00      1.00      0.00      0.00     99.00

01:13:57 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:58 AM     all      4.91      0.00      8.49      0.00      0.00     86.60
01:13:58 AM       0      3.45      0.00     13.79      0.00      0.00     82.76
01:13:58 AM       1      1.15      0.00     10.34      0.00      0.00     88.51
01:13:58 AM       2      1.02      0.00      2.04      0.00      0.00     96.94
01:13:58 AM       3      9.57      0.00      9.57      0.00      0.00     80.85
01:13:58 AM       4      5.15      0.00      4.12      0.00      0.00     90.72
01:13:58 AM       5     13.04      0.00     20.65      0.00      0.00     66.30
01:13:58 AM       6      4.12      0.00      8.25      0.00      0.00     87.63
01:13:58 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:58 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:13:59 AM     all      5.15      0.00      8.72      0.00      0.00     86.13
01:13:59 AM       0      3.41      0.00     13.64      0.00      0.00     82.95
01:13:59 AM       1      2.20      0.00     13.19      0.00      0.00     84.62
01:13:59 AM       2      1.04      0.00      2.08      0.00      0.00     96.88
01:13:59 AM       3      7.37      0.00      8.42      0.00      0.00     84.21
01:13:59 AM       4      7.22      0.00      7.22      0.00      0.00     85.57
01:13:59 AM       5     13.68      0.00     18.95      0.00      0.00     67.37
01:13:59 AM       6      5.26      0.00      8.42      0.00      0.00     86.32
01:13:59 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

01:13:59 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:14:00 AM     all      4.77      0.00      8.75      0.00      0.00     86.47
01:14:00 AM       0      3.41      0.00     14.77      0.00      0.00     81.82
01:14:00 AM       1      2.27      0.00     10.23      0.00      0.00     87.50
01:14:00 AM       2      0.00      0.00      1.06      0.00      0.00     98.94
01:14:00 AM       3      8.42      0.00      8.42      0.00      0.00     83.16
01:14:00 AM       4      4.12      0.00      6.19      0.00      0.00     89.69
01:14:00 AM       5     12.77      0.00     19.15      0.00      0.00     68.09
01:14:00 AM       6      7.22      0.00      9.28      0.00      0.00     83.51
01:14:00 AM       7      0.00      0.00      0.00      0.00      0.00    100.00

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all      4.85      0.00      8.71      0.00      0.00     86.45
Average:          0      3.26      0.00     12.98      0.00      0.00     83.75
Average:          1      1.72      0.00     10.49      0.00      0.00     87.79
Average:          2      1.46      0.00      4.46      0.00      0.00     94.07
Average:          3     10.40      0.00     10.68      0.00      0.00     78.92
Average:          4      3.83      0.00      4.51      0.00      0.00     91.67
Average:          5     15.16      0.00     22.85      0.00      0.00     61.99
Average:          6      3.00      0.00      4.90      0.00      0.00     92.10
Average:          7      0.00      0.00      0.07      0.00      0.00     99.93

groonga -d /var/lib/mysql/article_index.mrn -t 8 --cache-limit 0
perl bench_grn_gqtp.pl 8

[root@localhost vagrant]# sar -P ALL 1 15
Linux 2.6.32-279.el6.x86_64 (localhost.localdomain)     03/07/2014  _x86_64_    (8 CPU)

01:16:06 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:07 AM     all     17.67      0.00     39.76      0.00      0.00     42.57
01:16:07 AM       0     18.09      0.00     45.74      0.00      0.00     36.17
01:16:07 AM       1     14.89      0.00     45.74      0.00      0.00     39.36
01:16:07 AM       2     17.02      0.00     43.62      0.00      0.00     39.36
01:16:07 AM       3     18.48      0.00     38.04      0.00      0.00     43.48
01:16:07 AM       4     18.68      0.00     37.36      0.00      0.00     43.96
01:16:07 AM       5     18.28      0.00     38.71      0.00      0.00     43.01
01:16:07 AM       6     17.71      0.00     37.50      0.00      0.00     44.79
01:16:07 AM       7     17.02      0.00     34.04      0.00      0.00     48.94

01:16:07 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:08 AM     all     18.92      0.00     40.00      0.00      0.00     41.08
01:16:08 AM       0     18.75      0.00     46.88      0.00      0.00     34.38
01:16:08 AM       1     17.58      0.00     46.15      0.00      0.00     36.26
01:16:08 AM       2     18.28      0.00     43.01      0.00      0.00     38.71
01:16:08 AM       3     19.57      0.00     40.22      0.00      0.00     40.22
01:16:08 AM       4     20.88      0.00     37.36      0.00      0.00     41.76
01:16:08 AM       5     18.28      0.00     36.56      0.00      0.00     45.16
01:16:08 AM       6     19.35      0.00     34.41      0.00      0.00     46.24
01:16:08 AM       7     20.21      0.00     34.04      0.00      0.00     45.74

01:16:08 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:09 AM     all     18.55      0.00     40.05      0.00      0.00     41.40
01:16:09 AM       0     15.22      0.00     48.91      0.00      0.00     35.87
01:16:09 AM       1     21.05      0.00     42.11      1.05      0.00     35.79
01:16:09 AM       2     17.39      0.00     44.57      0.00      0.00     38.04
01:16:09 AM       3     17.58      0.00     40.66      0.00      0.00     41.76
01:16:09 AM       4     17.39      0.00     40.22      0.00      0.00     42.39
01:16:09 AM       5     16.30      0.00     35.87      0.00      0.00     47.83
01:16:09 AM       6     20.43      0.00     35.48      0.00      0.00     44.09
01:16:09 AM       7     22.34      0.00     32.98      0.00      0.00     44.68

01:16:09 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:10 AM     all     18.84      0.00     40.24      0.00      0.00     40.92
01:16:10 AM       0     16.48      0.00     48.35      0.00      0.00     35.16
01:16:10 AM       1     18.48      0.00     45.65      0.00      0.00     35.87
01:16:10 AM       2     18.28      0.00     44.09      0.00      0.00     37.63
01:16:10 AM       3     20.43      0.00     37.63      0.00      0.00     41.94
01:16:10 AM       4     20.65      0.00     39.13      0.00      0.00     40.22
01:16:10 AM       5     18.28      0.00     37.63      0.00      0.00     44.09
01:16:10 AM       6     21.05      0.00     36.84      0.00      0.00     42.11
01:16:10 AM       7     16.84      0.00     33.68      0.00      0.00     49.47

01:16:10 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:11 AM     all     18.12      0.00     38.56      0.00      0.00     43.32
01:16:11 AM       0     17.20      0.00     46.24      0.00      0.00     36.56
01:16:11 AM       1     16.85      0.00     41.57      0.00      0.00     41.57
01:16:11 AM       2     16.13      0.00     44.09      0.00      0.00     39.78
01:16:11 AM       3     16.67      0.00     38.89      0.00      0.00     44.44
01:16:11 AM       4     17.98      0.00     35.96      0.00      0.00     46.07
01:16:11 AM       5     19.35      0.00     37.63      0.00      0.00     43.01
01:16:11 AM       6     20.43      0.00     31.18      0.00      0.00     48.39
01:16:11 AM       7     19.15      0.00     34.04      0.00      0.00     46.81

01:16:11 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:12 AM     all     17.60      0.00     39.43      0.00      0.00     42.97
01:16:12 AM       0     16.13      0.00     48.39      0.00      0.00     35.48
01:16:12 AM       1     16.48      0.00     45.05      0.00      0.00     38.46
01:16:12 AM       2     15.73      0.00     43.82      0.00      0.00     40.45
01:16:12 AM       3     17.05      0.00     39.77      0.00      0.00     43.18
01:16:12 AM       4     16.30      0.00     36.96      0.00      0.00     46.74
01:16:12 AM       5     21.74      0.00     34.78      0.00      0.00     43.48
01:16:12 AM       6     18.48      0.00     34.78      0.00      0.00     46.74
01:16:12 AM       7     18.95      0.00     31.58      0.00      0.00     49.47

01:16:12 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:13 AM     all     18.67      0.00     39.51      0.00      0.00     41.81
01:16:13 AM       0     19.35      0.00     45.16      0.00      0.00     35.48
01:16:13 AM       1     18.89      0.00     42.22      0.00      0.00     38.89
01:16:13 AM       2     16.30      0.00     43.48      0.00      0.00     40.22
01:16:13 AM       3     19.57      0.00     40.22      0.00      0.00     40.22
01:16:13 AM       4     18.48      0.00     36.96      0.00      0.00     44.57
01:16:13 AM       5     17.39      0.00     35.87      0.00      0.00     46.74
01:16:13 AM       6     20.00      0.00     37.89      0.00      0.00     42.11
01:16:13 AM       7     20.21      0.00     32.98      0.00      0.00     46.81

01:16:13 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:14 AM     all     19.22      0.00     39.65      0.00      0.00     41.13
01:16:14 AM       0     18.95      0.00     46.32      0.00      0.00     34.74
01:16:14 AM       1     17.02      0.00     46.81      0.00      0.00     36.17
01:16:14 AM       2     17.39      0.00     42.39      0.00      0.00     40.22
01:16:14 AM       3     20.00      0.00     40.00      0.00      0.00     40.00
01:16:14 AM       4     18.68      0.00     39.56      0.00      0.00     41.76
01:16:14 AM       5     20.21      0.00     35.11      0.00      0.00     44.68
01:16:14 AM       6     19.35      0.00     34.41      0.00      0.00     46.24
01:16:14 AM       7     22.11      0.00     32.63      0.00      0.00     45.26

01:16:14 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:15 AM     all     18.27      0.00     40.87      0.00      0.00     40.87
01:16:15 AM       0     19.57      0.00     45.65      0.00      0.00     34.78
01:16:15 AM       1     17.98      0.00     43.82      0.00      0.00     38.20
01:16:15 AM       2     16.13      0.00     46.24      0.00      0.00     37.63
01:16:15 AM       3     16.48      0.00     41.76      0.00      0.00     41.76
01:16:15 AM       4     17.20      0.00     41.94      0.00      0.00     40.86
01:16:15 AM       5     17.20      0.00     38.71      0.00      0.00     44.09
01:16:15 AM       6     20.21      0.00     36.17      0.00      0.00     43.62
01:16:15 AM       7     21.28      0.00     35.11      0.00      0.00     43.62

01:16:15 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:16 AM     all     17.10      0.00     38.67      0.00      0.00     44.23
01:16:16 AM       0     16.30      0.00     44.57      0.00      0.00     39.13
01:16:16 AM       1     16.84      0.00     46.32      0.00      0.00     36.84
01:16:16 AM       2     16.85      0.00     40.45      0.00      0.00     42.70
01:16:16 AM       3     16.30      0.00     41.30      0.00      0.00     42.39
01:16:16 AM       4     18.68      0.00     36.26      0.00      0.00     45.05
01:16:16 AM       5     16.48      0.00     35.16      0.00      0.00     48.35
01:16:16 AM       6     15.05      0.00     35.48      0.00      0.00     49.46
01:16:16 AM       7     18.75      0.00     32.29      0.00      0.00     48.96

01:16:16 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:17 AM     all     18.45      0.00     39.76      0.00      0.00     41.79
01:16:17 AM       0     19.35      0.00     46.24      0.00      0.00     34.41
01:16:17 AM       1     15.91      0.00     43.18      0.00      0.00     40.91
01:16:17 AM       2     19.15      0.00     44.68      0.00      0.00     36.17
01:16:17 AM       3     19.54      0.00     34.48      0.00      0.00     45.98
01:16:17 AM       4     20.43      0.00     38.71      0.00      0.00     40.86
01:16:17 AM       5     15.38      0.00     35.16      0.00      0.00     49.45
01:16:17 AM       6     19.35      0.00     35.48      0.00      0.00     45.16
01:16:17 AM       7     20.00      0.00     35.79      0.00      0.00     44.21

01:16:17 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:18 AM     all     18.06      0.00     39.76      0.00      0.00     42.18
01:16:18 AM       0     18.95      0.00     46.32      0.00      0.00     34.74
01:16:18 AM       1     18.28      0.00     44.09      0.00      0.00     37.63
01:16:18 AM       2     16.67      0.00     41.11      0.00      0.00     42.22
01:16:18 AM       3     17.39      0.00     40.22      0.00      0.00     42.39
01:16:18 AM       4     18.28      0.00     39.78      0.00      0.00     41.94
01:16:18 AM       5     16.84      0.00     38.95      0.00      0.00     44.21
01:16:18 AM       6     17.39      0.00     34.78      0.00      0.00     47.83
01:16:18 AM       7     20.43      0.00     32.26      0.00      0.00     47.31

01:16:18 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:19 AM     all     17.77      0.00     39.89      0.00      0.00     42.33
01:16:19 AM       0     18.48      0.00     45.65      0.00      0.00     35.87
01:16:19 AM       1     16.48      0.00     45.05      0.00      0.00     38.46
01:16:19 AM       2     15.38      0.00     42.86      0.00      0.00     41.76
01:16:19 AM       3     16.48      0.00     39.56      0.00      0.00     43.96
01:16:19 AM       4     16.85      0.00     37.08      0.00      0.00     46.07
01:16:19 AM       5     19.35      0.00     38.71      0.00      0.00     41.94
01:16:19 AM       6     19.35      0.00     36.56      0.00      0.00     44.09
01:16:19 AM       7     18.95      0.00     34.74      0.00      0.00     46.32

01:16:19 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:20 AM     all     19.76      0.00     40.19      0.00      0.00     40.05
01:16:20 AM       0     17.39      0.00     47.83      0.00      0.00     34.78
01:16:20 AM       1     17.39      0.00     45.65      0.00      0.00     36.96
01:16:20 AM       2     20.43      0.00     43.01      0.00      0.00     36.56
01:16:20 AM       3     20.00      0.00     40.00      0.00      0.00     40.00
01:16:20 AM       4     23.91      0.00     36.96      0.00      0.00     39.13
01:16:20 AM       5     19.57      0.00     36.96      0.00      0.00     43.48
01:16:20 AM       6     17.89      0.00     35.79      0.00      0.00     46.32
01:16:20 AM       7     20.43      0.00     35.48      0.00      0.00     44.09

01:16:20 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:16:21 AM     all     17.86      0.00     40.05      0.00      0.00     42.08
01:16:21 AM       0     17.20      0.00     49.46      0.00      0.00     33.33
01:16:21 AM       1     16.30      0.00     44.57      0.00      0.00     39.13
01:16:21 AM       2     16.85      0.00     43.82      0.00      0.00     39.33
01:16:21 AM       3     18.89      0.00     38.89      0.00      0.00     42.22
01:16:21 AM       4     18.18      0.00     35.23      0.00      0.00     46.59
01:16:21 AM       5     18.28      0.00     37.63      0.00      0.00     44.09
01:16:21 AM       6     18.56      0.00     38.14      1.03      0.00     42.27
01:16:21 AM       7     19.39      0.00     32.65      0.00      0.00     47.96

Average:        CPU     %user     %nice   %system   %iowait    %steal     %idle
Average:        all     18.33      0.00     39.76      0.00      0.00     41.91
Average:          0     17.84      0.00     46.78      0.00      0.00     35.39
Average:          1     17.37      0.00     44.55      0.07      0.00     38.01
Average:          2     17.21      0.00     43.43      0.00      0.00     39.36
Average:          3     18.30      0.00     39.46      0.00      0.00     42.25
Average:          4     18.85      0.00     37.98      0.00      0.00     43.17
Average:          5     18.20      0.00     36.91      0.00      0.00     44.89
Average:          6     18.98      0.00     35.68      0.07      0.00     45.27
Average:          7     19.73      0.00     33.62      0.00      0.00     46.65

プロセス数8の場合 http://redmine.groonga.org/issues/2335#note-23 のMroongaの場合と比較すると、%user, %system, %idleの割合に同じ傾向が見られます。%systemの割合が高く、%idleしている割合が高いのはMroongaからではなく、Groongaに起因しているものと考えられます。

#70 Updated by Kenji Maruyama almost 4 years ago

原因の一つ: grn_table_size(ctx, grn_table) がボトルネックになっているようです。

void ha_mroonga::storage_info_variable_records()
{
  MRN_DBUG_ENTER_METHOD();

  stats.records = grn_table_size(ctx, grn_table);

  DBUG_VOID_RETURN;
}

storage_info_variable_recordsをコメントアウトすると、実環境で以下のクエリ, 8プロセス同時実行,元々40数秒が2秒になりました。

SELECT SQL_NO_CACHE article_id FROM article_index_0099 LIMIT 500;

さらに検証した結果は以下になります。

問題あり

  • CONCAT_WS
  • CONCAT_WS なしだが、+(livedoor ブログ blog 開発) または、 +(livedoor blog ブログ) または、 +(livedoor ブログ blog) または +(ブログ livedoor blog)

問題なし

  • CONCAT_WS なしで +(livedoor blog) または、+livedoor +blog または、+livedoor +ブログ +blog, または、+livedoor +ブログ +blog +開発

上のクエリはCONCAT_WSを除いて以下の ? に代入して検証しました。

SELECT SQL_NO_CACHE SQL_CALC_FOUND_ROWS article_id FROM article_index_0099 WHERE blog_id=30 AND status=1 AND MATCH(public_terms) AGAINST(? IN BOOLEAN MODE) ORDER BY regist_datetime DESC LIMIT 10 OFFSET 0

grn_table_size は他にも影響大きいので、このボトルネックを解消すると上記の問題ありのクエリも治るかもしれません。

マルチスレッドでのgrn_table_sizeの挙動が気になるところです。

#71 Updated by Kouhei Sutou almost 4 years ago

Kenji Maruyama wrote:

原因の一つ: grn_table_size(ctx, grn_table) がボトルネックになっているようです。

え。。。これは、単に構造体のフィールドの値を返しているだけですよ。。。


void ha_mroonga::storage_info_variable_records()
{
MRN_DBUG_ENTER_METHOD();
stats.records = grn_table_size(ctx, grn_table);
DBUG_VOID_RETURN;
}

storage_info_variable_recordsをコメントアウトすると、実環境で以下のクエリ, 8プロセス同時実行,元々40数秒が2秒になりました。

これ、コメントアウトするってことは毎回stats.recordsが0のままになるってことですよね?それで速くなっているだけだったりしません?stats.records = 1000;とか実際にgrn_table_size(ctx, grn_table);が返す値をいれても同じように速くなりますか?

(私は、MySQLに返すレコードを設定している以外の処理じゃなくて、設定している周りの処理をコメントアウトしたり定数にしたりしながら絞り込むのがよいと思うのですが。。。)

#72 Updated by Kenji Maruyama almost 4 years ago

原因の一つ: grn_table_size(ctx, grn_table) がボトルネックになっているようです。

コメントアウトせずに、grn_table_sizeの所定数1に変えて "stats.records = 1" すると、8プロセス同時実行,元々40数秒が2秒になるのは変わりません。

ただ、stats.records >= 2 以上にすると、8プロセス同時実行で40数秒かかるようになります。grn_table_size自体に問題はないようです。

#73 Updated by Kenji Maruyama almost 4 years ago

(私は、MySQLに返すレコードを設定している以外の処理じゃなくて、設定している周りの処理をコメントアウトしたり定数にしたりしながら絞り込むのがよいと思うのですが。。。)

絞り込み方が悪いかもしれませんが、LIMIT数が多いとボトルネックになるようなので、最初はループの数に関係すると思い、ループになっている関数をすべてコメントアウトしていたのですが、効果なしでした。その後、トレースに現れるmrn, ha_mroongaをすべて列挙して上から順にコメントアウトしたりして確認しているところです。

64307:T@3    : | | | | | | | | | | | | info: setting dbtype to 'mroonga' (42)
64344:T@3    : | | | | | | | | | | | | | >mrn_handler_create
64354:T@3    : | | | | | | | | | | | | | | >ha_mroonga::ha_mroonga
64357:T@3    : | | | | | | | | | | | | | | <ha_mroonga::ha_mroonga 1946
64358:T@3    : | | | | | | | | | | | | | <mrn_handler_create 949
64359:T@3    : | | | | | | | | | | | | | >ha_mroonga::table_flags
64360:T@3    : | | | | | | | | | | | | | | >ha_mroonga::storage_table_flags
64361:T@3    : | | | | | | | | | | | | | | <ha_mroonga::storage_table_flags 2244
64362:T@3    : | | | | | | | | | | | | | <ha_mroonga::table_flags 2269
64525:T@3    : | | | | | | | | | | | | | >ha_mroonga::storage_index_flags
64526:T@3    : | | | | | | | | | | | | | | >ha_mroonga::should_normalize
64527:T@3    : | | | | | | | | | | | | | | | >mrn::FieldNormalizer::should_normalize
64528:T@3    : | | | | | | | | | | | | | | | | info: mroonga: result_type = 2
64529:T@3    : | | | | | | | | | | | | | | | | info: mroonga: charset->name = latin1_swedish_ci
64530:T@3    : | | | | | | | | | | | | | | | | info: mroonga: charset->csname = latin1
64531:T@3    : | | | | | | | | | | | | | | | | info: mroonga: charset->state = 801
64532:T@3    : | | | | | | | | | | | | | | | | >mrn::FieldNormalizer::is_text_type
64533:T@3    : | | | | | | | | | | | | | | | | <mrn::FieldNormalizer::is_text_type 89
64534:T@3    : | | | | | | | | | | | | | | | | info: mroonga: should_normalize: false: no text type
64535:T@3    : | | | | | | | | | | | | | | | <mrn::FieldNormalizer::should_normalize 62
64536:T@3    : | | | | | | | | | | | | | | <ha_mroonga::should_normalize 8697
64537:T@3    : | | | | | | | | | | | | | <ha_mroonga::storage_index_flags 2310
64538:T@3    : | | | | | | | | | | | | <ha_mroonga::index_flags 2332
64612:T@3    : | | | | | | | | | | | | >ha_mroonga::~ha_mroonga
64613:T@3    : | | | | | | | | | | | | <ha_mroonga::~ha_mroonga 1974
64655:T@3    : | | | | | | | | | | >mrn_handler_create
64665:T@3    : | | | | | | | | | | | >ha_mroonga::ha_mroonga
64668:T@3    : | | | | | | | | | | | <ha_mroonga::ha_mroonga 1946
64669:T@3    : | | | | | | | | | | <mrn_handler_create 949
64670:T@3    : | | | | | | | | | | >ha_mroonga::table_flags
64671:T@3    : | | | | | | | | | | | >ha_mroonga::storage_table_flags
64672:T@3    : | | | | | | | | | | | <ha_mroonga::storage_table_flags 2244
64673:T@3    : | | | | | | | | | | <ha_mroonga::table_flags 2269
64744:T@3    : | | | | | | | | | | >ha_mroonga::open
64745:T@3    : | | | | | | | | | | | >mrn_get_share
64754:T@3    : | | | | | | | | | | | | >mrn_parse_table_param
64755:T@3    : | | | | | | | | | | | | | >mrn_get_partition_info
64756:T@3    : | | | | | | | | | | | | | <mrn_get_partition_info 192
64757:T@3    : | | | | | | | | | | | | <mrn_parse_table_param 459
64758:T@3    : | | | | | | | | | | | | >mrn_parse_column_param
64759:T@3    : | | | | | | | | | | | | <mrn_parse_column_param 689
64760:T@3    : | | | | | | | | | | | | >mrn_parse_index_param
64791:T@3    : | | | | | | | | | | | | | >mrn_add_index_param
64796:T@3    : | | | | | | | | | | | | | <mrn_add_index_param 496
64797:T@3    : | | | | | | | | | | | | <mrn_parse_index_param 591
64801:T@3    : | | | | | | | | | | | | >mrn_get_long_term_share
64802:T@3    : | | | | | | | | | | | | | info: mroonga: table_name=./article_index/article_index_0099
64811:T@3    : | | | | | | | | | | | | | >mrn_long_term_share_get_key
64812:T@3    : | | | | | | | | | | | | | <mrn_long_term_share_get_key 482
64813:T@3    : | | | | | | | | | | | | <mrn_get_long_term_share 770
64814:T@3    : | | | | | | | | | | | | >mrn_open_tables_get_key
64815:T@3    : | | | | | | | | | | | | <mrn_open_tables_get_key 471
64816:T@3    : | | | | | | | | | | | <mrn_get_share 913
64823:T@3    : | | | | | | | | | | | >ha_mroonga::storage_open
64824:T@3    : | | | | | | | | | | | | >ha_mroonga::ensure_database_open
64827:T@3    : | | | | | | | | | | | | | >ha_mroonga::ensure_normalizers_register
64828:T@3    : | | | | | | | | | | | | | <ha_mroonga::ensure_normalizers_register 3498
64829:T@3    : | | | | | | | | | | | | <ha_mroonga::ensure_database_open 3577
64830:T@3    : | | | | | | | | | | | | >ha_mroonga::open_table
64833:T@3    : | | | | | | | | | | | | <ha_mroonga::open_table 3942
64834:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_open_columns
64837:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_open_columns 3996
64838:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_open_indexes
64848:T@3    : | | | | | | | | | | | | | >mrn::IndexTableName::encode
64849:T@3    : | | | | | | | | | | | | | | info: mroonga: in=unique_entry
64850:T@3    : | | | | | | | | | | | | | | info: mroonga: out=unique_entry
64851:T@3    : | | | | | | | | | | | | | <mrn::IndexTableName::encode 87
64852:T@3    : | | | | | | | | | | | | | >mrn_free_share
64853:T@3    : | | | | | | | | | | | | | <mrn_free_share 948
64861:T@3    : | | | | | | | | | | | | | >mrn::IndexTableName::encode
64862:T@3    : | | | | | | | | | | | | | | info: mroonga: in=article_status
64863:T@3    : | | | | | | | | | | | | | | info: mroonga: out=article_status
64864:T@3    : | | | | | | | | | | | | | <mrn::IndexTableName::encode 87
64865:T@3    : | | | | | | | | | | | | | >mrn_free_share
64866:T@3    : | | | | | | | | | | | | | <mrn_free_share 948
64867:T@3    : | | | | | | | | | | | | | >mrn_get_share
64869:T@3    : | | | | | | | | | | | | | | | >mrn_open_tables_get_key
64870:T@3    : | | | | | | | | | | | | | | | <mrn_open_tables_get_key 471
64873:T@3    : | | | | | | | | | | | | | <mrn_get_share 913
64874:T@3    : | | | | | | | | | | | | | >mrn::IndexTableName::encode
64875:T@3    : | | | | | | | | | | | | | | info: mroonga: in=regist_datetime
64876:T@3    : | | | | | | | | | | | | | | info: mroonga: out=regist_datetime
64877:T@3    : | | | | | | | | | | | | | <mrn::IndexTableName::encode 87
64878:T@3    : | | | | | | | | | | | | | >mrn_free_share
64879:T@3    : | | | | | | | | | | | | | <mrn_free_share 948
64880:T@3    : | | | | | | | | | | | | | >mrn_get_share
64882:T@3    : | | | | | | | | | | | | | | | >mrn_open_tables_get_key
64883:T@3    : | | | | | | | | | | | | | | | <mrn_open_tables_get_key 471
64886:T@3    : | | | | | | | | | | | | | <mrn_get_share 913
64887:T@3    : | | | | | | | | | | | | | >mrn::IndexTableName::encode
64888:T@3    : | | | | | | | | | | | | | | info: mroonga: in=for_public
64889:T@3    : | | | | | | | | | | | | | | info: mroonga: out=for_public
64890:T@3    : | | | | | | | | | | | | | <mrn::IndexTableName::encode 87
64891:T@3    : | | | | | | | | | | | | | >mrn_free_share
64892:T@3    : | | | | | | | | | | | | | <mrn_free_share 948
64893:T@3    : | | | | | | | | | | | | | >mrn_get_share
64895:T@3    : | | | | | | | | | | | | | | | >mrn_open_tables_get_key
64896:T@3    : | | | | | | | | | | | | | | | <mrn_open_tables_get_key 471
64899:T@3    : | | | | | | | | | | | | | <mrn_get_share 913
64900:T@3    : | | | | | | | | | | | | | >mrn::IndexTableName::encode
64901:T@3    : | | | | | | | | | | | | | | info: mroonga: in=for_cms
64902:T@3    : | | | | | | | | | | | | | | info: mroonga: out=for_cms
64903:T@3    : | | | | | | | | | | | | | <mrn::IndexTableName::encode 87
64904:T@3    : | | | | | | | | | | | | | >mrn_free_share
64905:T@3    : | | | | | | | | | | | | | <mrn_free_share 948
64906:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_open_indexes 4111
64907:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_set_keys_in_use
64908:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_set_keys_in_use 4485
64909:T@3    : | | | | | | | | | | | <ha_mroonga::storage_open 3913
64910:T@3    : | | | | | | | | | | <ha_mroonga::open 4143
64911:T@3    : | | | | | | | | | | >ha_mroonga::extra
64912:T@3    : | | | | | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_NO_READCHECK
64913:T@3    : | | | | | | | | | | | >ha_mroonga::storage_extra
64914:T@3    : | | | | | | | | | | | <ha_mroonga::storage_extra 4954
64915:T@3    : | | | | | | | | | | | >ha_mroonga::generic_extra
64916:T@3    : | | | | | | | | | | | <ha_mroonga::generic_extra 4936
64917:T@3    : | | | | | | | | | | <ha_mroonga::extra 4972
64922:T@3    : | | | | | | | | | | >ha_mroonga::table_flags
64923:T@3    : | | | | | | | | | | | >ha_mroonga::storage_table_flags
64924:T@3    : | | | | | | | | | | | <ha_mroonga::storage_table_flags 2244
64925:T@3    : | | | | | | | | | | <ha_mroonga::table_flags 2269
64959:T@3    : | | | | | | | >ha_mroonga::extra
64960:T@3    : | | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_ADD_CHILDREN_LIST
64961:T@3    : | | | | | | | | >ha_mroonga::storage_extra
64962:T@3    : | | | | | | | | <ha_mroonga::storage_extra 4954
64963:T@3    : | | | | | | | | >ha_mroonga::generic_extra
64964:T@3    : | | | | | | | | <ha_mroonga::generic_extra 4936
64965:T@3    : | | | | | | | <ha_mroonga::extra 4972
65045:T@3    : | | | | | | | | | >ha_mroonga::lock_count
65046:T@3    : | | | | | | | | | | >ha_mroonga::storage_lock_count
65047:T@3    : | | | | | | | | | | <ha_mroonga::storage_lock_count 4642
65048:T@3    : | | | | | | | | | <ha_mroonga::lock_count 4655
65053:T@3    : | | | | | | | | | >ha_mroonga::store_lock
65054:T@3    : | | | | | | | | | | info: mroonga: lock_type=TL_READ
65055:T@3    : | | | | | | | | | | >ha_mroonga::storage_store_lock
65056:T@3    : | | | | | | | | | | <ha_mroonga::storage_store_lock 4687
65057:T@3    : | | | | | | | | | <ha_mroonga::store_lock 4700
65067:T@3    : | | | | | | | | | | >ha_mroonga::external_lock
65068:T@3    : | | | | | | | | | | | >ha_mroonga::storage_external_lock
65069:T@3    : | | | | | | | | | | | <ha_mroonga::storage_external_lock 4718
65070:T@3    : | | | | | | | | | | <ha_mroonga::external_lock 4732
65071:T@3    : | | | | | | | | | | >ha_mroonga::table_flags
65072:T@3    : | | | | | | | | | | | >ha_mroonga::storage_table_flags
65073:T@3    : | | | | | | | | | | | <ha_mroonga::storage_table_flags 2244
65074:T@3    : | | | | | | | | | | <ha_mroonga::table_flags 2269
65140:T@3    : | | | | | | | | >ha_mroonga::info
65141:T@3    : | | | | | | | | | >ha_mroonga::storage_info
65144:T@3    : | | | | | | | | | | >ha_mroonga::storage_info_variable
65145:T@3    : | | | | | | | | | | | >ha_mroonga::storage_info_variable_records
65146:T@3    : | | | | | | | | | | | <ha_mroonga::storage_info_variable_records 4589
65147:T@3    : | | | | | | | | | | | >ha_mroonga::storage_info_variable_data_file_length
65164:T@3    : | | | | | | | | | | | | >ha_mroonga::file_size
65165:T@3    : | | | | | | | | | | | | <ha_mroonga::file_size 8200
65166:T@3    : | | | | | | | | | | | <ha_mroonga::storage_info_variable_data_file_length 4610
65167:T@3    : | | | | | | | | | | <ha_mroonga::storage_info_variable 4580
65168:T@3    : | | | | | | | | | <ha_mroonga::storage_info 4570
65169:T@3    : | | | | | | | | <ha_mroonga::info 4624
65201:T@3    : | | | | | | | | >ha_mroonga::scan_time
65202:T@3    : | | | | | | | | | >ha_mroonga::storage_scan_time
65203:T@3    : | | | | | | | | | <ha_mroonga::storage_scan_time 11453
65204:T@3    : | | | | | | | | <ha_mroonga::scan_time 11466
65241:T@3    : | | | | | | | | | | | | >ha_mroonga::scan_time
65242:T@3    : | | | | | | | | | | | | | >ha_mroonga::storage_scan_time
65243:T@3    : | | | | | | | | | | | | | <ha_mroonga::storage_scan_time 11453
65244:T@3    : | | | | | | | | | | | | <ha_mroonga::scan_time 11466
65367:T@3    : | | | | | | | | >ha_mroonga::primary_key_is_clustered
65368:T@3    : | | | | | | | | | >ha_mroonga::storage_primary_key_is_clustered
65369:T@3    : | | | | | | | | | <ha_mroonga::storage_primary_key_is_clustered 14340
65370:T@3    : | | | | | | | | <ha_mroonga::primary_key_is_clustered 14353
65419:T@3    : | | | | | | | | | >ha_mroonga::extra
65420:T@3    : | | | | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_KEYREAD
65421:T@3    : | | | | | | | | | | >ha_mroonga::storage_extra
65422:T@3    : | | | | | | | | | | <ha_mroonga::storage_extra 4954
65423:T@3    : | | | | | | | | | | >ha_mroonga::generic_extra
65424:T@3    : | | | | | | | | | | <ha_mroonga::generic_extra 4936
65425:T@3    : | | | | | | | | | <ha_mroonga::extra 4972
65427:T@3    : | | | | | | | | | | >ha_mroonga::index_init
65428:T@3    : | | | | | | | | | | | info: mroonga: idx=1
65429:T@3    : | | | | | | | | | | | >ha_mroonga::storage_index_init
65430:T@3    : | | | | | | | | | | | <ha_mroonga::storage_index_init 6559
65431:T@3    : | | | | | | | | | | <ha_mroonga::index_init 6574
65433:T@3    : | | | | | | | | | >ha_mroonga::index_first
65434:T@3    : | | | | | | | | | | >ha_mroonga::storage_index_first
65435:T@3    : | | | | | | | | | | | >ha_mroonga::clear_cursor
65436:T@3    : | | | | | | | | | | | <ha_mroonga::clear_cursor 8239
65439:T@3    : | | | | | | | | | | | info: mroonga: use multiple column key1
65440:T@3    : | | | | | | | | | | | >ha_mroonga::storage_get_next_record
65441:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_store_fields_by_index
65442:T@3    : | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::decode
65443:T@3    : | | | | | | | | | | | | | | info: mroonga: n_key_parts=2
65444:T@3    : | | | | | | | | | | | | | | info: mroonga: key_part->length=4
65445:T@3    : | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
65446:T@3    : | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
65447:T@3    : | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
65448:T@3    : | | | | | | | | | | | | | | info: mroonga: key_part->length=4
65449:T@3    : | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
65450:T@3    : | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
65451:T@3    : | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
65452:T@3    : | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::decode 254
65453:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_store_fields_by_index 10088
65454:T@3    : | | | | | | | | | | | <ha_mroonga::storage_get_next_record 8611
65455:T@3    : | | | | | | | | | | <ha_mroonga::storage_index_first 7046
65456:T@3    : | | | | | | | | | <ha_mroonga::index_first 7059
65507:T@3    : | | | | | | | | | | >ha_mroonga::index_next
65508:T@3    : | | | | | | | | | | | >ha_mroonga::storage_index_next
65509:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_get_next_record
65510:T@3    : | | | | | | | | | | | | | >ha_mroonga::storage_store_fields_by_index
65511:T@3    : | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::decode
65512:T@3    : | | | | | | | | | | | | | | | info: mroonga: n_key_parts=2
65513:T@3    : | | | | | | | | | | | | | | | info: mroonga: key_part->length=4
65514:T@3    : | | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
65515:T@3    : | | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
65516:T@3    : | | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
65517:T@3    : | | | | | | | | | | | | | | | info: mroonga: key_part->length=4
65518:T@3    : | | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
65519:T@3    : | | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
65520:T@3    : | | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
65521:T@3    : | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::decode 254
65522:T@3    : | | | | | | | | | | | | | <ha_mroonga::storage_store_fields_by_index 10088
65523:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_get_next_record 8611
65524:T@3    : | | | | | | | | | | | <ha_mroonga::storage_index_next 6938
65525:T@3    : | | | | | | | | | | <ha_mroonga::index_next 6951
82945:T@3    : | | | | | | | | | | >ha_mroonga::extra
82946:T@3    : | | | | | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_NO_KEYREAD
82947:T@3    : | | | | | | | | | | | >ha_mroonga::storage_extra
82948:T@3    : | | | | | | | | | | | <ha_mroonga::storage_extra 4954
82949:T@3    : | | | | | | | | | | | >ha_mroonga::generic_extra
82950:T@3    : | | | | | | | | | | | <ha_mroonga::generic_extra 4936
82951:T@3    : | | | | | | | | | | <ha_mroonga::extra 4972
82954:T@3    : | | | | | | | | | | >ha_mroonga::index_end
82955:T@3    : | | | | | | | | | | | >ha_mroonga::storage_index_end
82956:T@3    : | | | | | | | | | | | | >ha_mroonga::clear_cursor
82957:T@3    : | | | | | | | | | | | | <ha_mroonga::clear_cursor 8239
82958:T@3    : | | | | | | | | | | | | >ha_mroonga::clear_cursor_geo
82959:T@3    : | | | | | | | | | | | | <ha_mroonga::clear_cursor_geo 8249
82960:T@3    : | | | | | | | | | | | <ha_mroonga::storage_index_end 6594
82961:T@3    : | | | | | | | | | | <ha_mroonga::index_end 6607
82992:T@3    : | | | | | | | | | | >ha_mroonga::extra
82993:T@3    : | | | | | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_NO_CACHE
82994:T@3    : | | | | | | | | | | | >ha_mroonga::storage_extra
82995:T@3    : | | | | | | | | | | | <ha_mroonga::storage_extra 4954
82996:T@3    : | | | | | | | | | | | >ha_mroonga::generic_extra
82997:T@3    : | | | | | | | | | | | <ha_mroonga::generic_extra 4936
82998:T@3    : | | | | | | | | | | <ha_mroonga::extra 4972
83064:T@3    : | | | | | >ha_mroonga::extra
83065:T@3    : | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_DETACH_CHILDREN
83066:T@3    : | | | | | | >ha_mroonga::storage_extra
83067:T@3    : | | | | | | <ha_mroonga::storage_extra 4954
83068:T@3    : | | | | | | >ha_mroonga::generic_extra
83069:T@3    : | | | | | | <ha_mroonga::generic_extra 4936
83070:T@3    : | | | | | <ha_mroonga::extra 4972
83078:T@3    : | | | | | | | | >ha_mroonga::external_lock
83079:T@3    : | | | | | | | | | >ha_mroonga::storage_external_lock
83080:T@3    : | | | | | | | | | <ha_mroonga::storage_external_lock 4718
83081:T@3    : | | | | | | | | <ha_mroonga::external_lock 4732
83082:T@3    : | | | | | | | | >ha_mroonga::table_flags
83083:T@3    : | | | | | | | | | >ha_mroonga::storage_table_flags
83084:T@3    : | | | | | | | | | <ha_mroonga::storage_table_flags 2244
83085:T@3    : | | | | | | | | <ha_mroonga::table_flags 2269
83094:T@3    : | | | | | | >ha_mroonga::extra
83095:T@3    : | | | | | | | info: mroonga: this=0x2aa3c70; extra-operation=HA_EXTRA_DETACH_CHILDREN
83096:T@3    : | | | | | | | >ha_mroonga::storage_extra
83097:T@3    : | | | | | | | <ha_mroonga::storage_extra 4954
83098:T@3    : | | | | | | | >ha_mroonga::generic_extra
83099:T@3    : | | | | | | | <ha_mroonga::generic_extra 4936
83100:T@3    : | | | | | | <ha_mroonga::extra 4972
83104:T@3    : | | | | | | | >ha_mroonga::reset
83105:T@3    : | | | | | | | | info: mroonga: this=0x2aa3c70
83106:T@3    : | | | | | | | | >ha_mroonga::clear_empty_value_records
83107:T@3    : | | | | | | | | <ha_mroonga::clear_empty_value_records 8263
83108:T@3    : | | | | | | | | >ha_mroonga::clear_search_result
83109:T@3    : | | | | | | | | | >ha_mroonga::clear_cursor
83110:T@3    : | | | | | | | | | <ha_mroonga::clear_cursor 8239
83111:T@3    : | | | | | | | | <ha_mroonga::clear_search_result 8278
83112:T@3    : | | | | | | | | >ha_mroonga::clear_search_result_geo
83113:T@3    : | | | | | | | | | >ha_mroonga::clear_cursor_geo
83114:T@3    : | | | | | | | | | <ha_mroonga::clear_cursor_geo 8249
83115:T@3    : | | | | | | | | <ha_mroonga::clear_search_result_geo 8289
83116:T@3    : | | | | | | | | >ha_mroonga::storage_reset
83117:T@3    : | | | | | | | | | >ha_mroonga::generic_reset
83118:T@3    : | | | | | | | | | <ha_mroonga::generic_reset 10656
83119:T@3    : | | | | | | | | <ha_mroonga::storage_reset 10692
83120:T@3    : | | | | | | | | >mrn_clear_alter_share
83121:T@3    : | | | | | | | | | >mrn_get_slot_data
83122:T@3    : | | | | | | | | | | >mrn_allocated_thds_get_key
83123:T@3    : | | | | | | | | | | <mrn_allocated_thds_get_key 556
83124:T@3    : | | | | | | | | | <mrn_get_slot_data 1089
83125:T@3    : | | | | | | | | <mrn_clear_alter_share 1120
83126:T@3    : | | | | | | | <ha_mroonga::reset 10717
83128:T@3    : | | | | | | >ha_mroonga::unbind_psi
83129:T@3    : | | | | | | | >ha_mroonga::storage_unbind_psi
83130:T@3    : | | | | | | | <ha_mroonga::storage_unbind_psi 14936
83131:T@3    : | | | | | | <ha_mroonga::unbind_psi 14949
83176:T@3    : | | | | | | info: unlocking plugin, name= mroonga, ref_count= 2
83415:T@3    : | | >mrn_close_connection
83416:T@3    : | | | >mrn_clear_alter_share
83417:T@3    : | | | | >mrn_get_slot_data
83418:T@3    : | | | | <mrn_get_slot_data 1089
83419:T@3    : | | | <mrn_clear_alter_share 1120
83421:T@3    : | | | | >mrn_allocated_thds_get_key
83422:T@3    : | | | | <mrn_allocated_thds_get_key 556
83424:T@3    : | | <mrn_close_connection 994
85552:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_action_on_fulltext_query_error'  wildstr: 'pid_file'
85555:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_database_path_prefix'  wildstr: 'pid_file'
85558:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_default_parser'  wildstr: 'pid_file'
85561:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_default_wrapper_engine'  wildstr: 'pid_file'
85564:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_dry_write'  wildstr: 'pid_file'
85567:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_enable_optimization'  wildstr: 'pid_file'
85570:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_libgroonga_version'  wildstr: 'pid_file'
85573:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_lock_timeout'  wildstr: 'pid_file'
85576:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_log_file'  wildstr: 'pid_file'
85579:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_log_level'  wildstr: 'pid_file'
85582:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_match_escalation_threshold'  wildstr: 'pid_file'
85585:T@3    : | | | | | | | | | | | | enter: str: 'mroonga_version'  wildstr: 'pid_file'
91979:T@4    : | | | | >ha_mroonga::close
91980:T@4    : | | | | | >ha_mroonga::clear_indexes
91981:T@4    : | | | | | <ha_mroonga::clear_indexes 8329
91982:T@4    : | | | | | >ha_mroonga::storage_close
91983:T@4    : | | | | | <ha_mroonga::storage_close 4179
91984:T@4    : | | | | | >ha_mroonga::is_temporary_table_name
91985:T@4    : | | | | | | info: mroonga: table name = ./article_index/article_index_0099
91986:T@4    : | | | | | <ha_mroonga::is_temporary_table_name 8718
91992:T@4    : | | | | | >mrn_free_share
91994:T@4    : | | | | | | | >mrn_open_tables_get_key
91995:T@4    : | | | | | | | <mrn_open_tables_get_key 471
91997:T@4    : | | | | | | >mrn_free_share_alloc
92016:T@4    : | | | | | | <mrn_free_share_alloc 718
92020:T@4    : | | | | | <mrn_free_share 948
92021:T@4    : | | | | <ha_mroonga::close 4244
92025:T@4    : | | | | >ha_mroonga::~ha_mroonga
92026:T@4    : | | | | <ha_mroonga::~ha_mroonga 1974
92043:T@4    : | | | | | | | | | | | info: unlocking plugin, name= mroonga, ref_count= 1
92328:T@4    : | | | | | enter: buffer: Shutting down plugin 'mroonga'
92333:T@4    : | | | info: Deinitializing plugin: 'mroonga'
92334:T@4    : | | | >mrn_free_long_term_share
92336:T@4    : | | | | | >mrn_long_term_share_get_key
92337:T@4    : | | | | | <mrn_long_term_share_get_key 482
92342:T@4    : | | | <mrn_free_long_term_share 730

#74 Updated by Kenji Maruyama almost 4 years ago

ただ、stats.records >= 2 以上にすると、8プロセス同時実行で40数秒かかるようになります。

オプティマイザーの動きが0,1の場合と2以上の場合とで動きが変わるようですね。失礼しました。

https://dev.mysql.com/doc/internals/en/implementing-info-method.html

For the purposes of a table scan, the most important property is records, which indicates the number of records in the table. The optimizer will perform differently when the storage engine indicates that there are zero or one rows in the table than it will when there are two or more. For this reason it is important to return a value of two or greater when you do not actually know how many rows are in the table before you perform the table scan (such as in a situation where the data may be externally populated). 

#75 Updated by Kenji Maruyama almost 4 years ago

最初はループの数に関係すると思い、ループになっている関数をすべてコメントアウトしていたのですが、効果なしでした。

ループ部分のコメントアウトした結果載せておくと、内側から処理を省略していくと徐々に処理時間は短くなるようですがボトルネックだと断定する箇所はありませんでした。

10124 82867:T@3    : | | | | | | | | | | >ha_mroonga::index_next
10125 82868:T@3    : | | | | | | | | | | | >ha_mroonga::storage_index_next
10126 82869:T@3    : | | | | | | | | | | | | >ha_mroonga::storage_get_next_record
10127 82870:T@3    : | | | | | | | | | | | | | >ha_mroonga::storage_store_fields_by_index
10128 82871:T@3    : | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::decode
10129 82872:T@3    : | | | | | | | | | | | | | | | info: mroonga: n_key_parts=2
10130 82873:T@3    : | | | | | | | | | | | | | | | info: mroonga: key_part->length=4
10131 82874:T@3    : | | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
10132 82875:T@3    : | | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
10133 82876:T@3    : | | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
10134 82877:T@3    : | | | | | | | | | | | | | | | info: mroonga: key_part->length=4
10135 82878:T@3    : | | | | | | | | | | | | | | | >mrn::MultipleColumnKeyCodec::get_key_info
10136 82879:T@3    : | | | | | | | | | | | | | | | | info: mroonga: MYSQL_TYPE_LONG
10137 82880:T@3    : | | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::get_key_info 427
10138 82881:T@3    : | | | | | | | | | | | | | | <mrn::MultipleColumnKeyCodec::decode 254
10139 82882:T@3    : | | | | | | | | | | | | | <ha_mroonga::storage_store_fields_by_index 10088
10140 82883:T@3    : | | | | | | | | | | | | <ha_mroonga::storage_get_next_record 8611
10141 82884:T@3    : | | | | | | | | | | | <ha_mroonga::storage_index_next 6938
10142 82885:T@3    : | | | | | | | | | | <ha_mroonga::index_next 6951

何もしない場合

perl 500.pl 8 done: 45.2984910011292

mrn::MultipleColumnKeyCodec::decode 部分 をコメントアウト

+------------+
| article_id |
+------------+
|          0 |
中略… 
|          0 |
|          0 |
+------------+
500 rows in set (0.00 sec)

perl 500.pl 8
done: 34.5798709392548

ha_mroonga::storage_get_next_record 部分 をコメントアウト

+------------+
| article_id |
+------------+
|          0 |
中略… 
|          0 |
|          0 |
+------------+

perl 500.pl 8
done: 30.7542769908905

storage_index_next 部分 をコメントアウト

+------------+
| article_id |
+------------+
|         39 |
中略… 
|         39 |
|         39 |
+------------+
500 rows in set (0.01 sec)

perl 500.pl 8
done: 24.638885974884

#76 Updated by Kenji Maruyama almost 4 years ago

SELECT SQL_NO_CACHE article_id FROM article_index_0099 LIMIT 500;

念のため、上記のクエリ時のそれぞれのストレージエンジンの比較をしてみました。Mroongaだけ突出してスケールしないというわけでもなさそうです。InnoDB, Myisamと同じような傾向で, プロセス数が1から2, 3へと上がるときに急激に処理時間がかかるようになるが、その後緩やかに処理時間がかかるようになります。http://redmine.groonga.org/issues/2335#note-7 と比較すると、クエリによってInnoDBも性能が悪化することがわかります。


InnoDB

mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 1
done: 5.66816306114197
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 2
done: 8.89195489883423
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 3
done: 12.9263868331909
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 4
done: 17.1166861057281
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 5
done: 18.1112599372864
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 6
done: 19.4728770256042
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 7
done: 21.4476490020752
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 8
done: 24.0436658859253

myisam

mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 1
done: 3.73416614532471
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 2
done: 11.7679119110107
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 3
done: 26.7565369606018
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 4
done: 20.2097949981689
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 5
done: 37.1536870002747
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 6
done: 25.6972160339355
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 7
done: 28.0388870239258
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 8
done: 31.7523300647736


mroonga

mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 1
done: 5.61273908615112
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 2
done: 15.1464538574219
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 3
done: 20.1553449630737
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 4
done: 32.67937707901
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 5
done: 30.8171961307526
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 6
done: 35.8636150360107
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 7
done: 39.9674561023712
mmmaru777@s37:~/mrn_bugs/2335$ perl 500.pl 8
done: 45.4144048690796

Also available in: Atom PDF