Python の起動は早いのに、Qt モジュールをロードするようにしたとたんに 起動に 4 秒弱かかるようになる。 一方、Ryby/Qte のほうはと思えば、 Ruby/Qte メモにおいて「起動時間は・・考えないことにしよう」とあるから、 事情は同じらしい (なにげにほっとしてたりして)。 Qt アプリの起動は高速起動モード使ってるのであまり気にしたことはなかったが、 Python や Ruby のような console アプリで高速起動モードという訳にもいかんだろう。
てことで、調べたもの。
次の citytime の起動シーケンスは、 strace -tt の発行時刻を起動時からの経過時間に直したものである。
00:00:00.000000 execve("/home/QtPalmtop/bin/citytime", ["citytime"], [/* 21 vars */]) = 0
00:00:00.010846 uname({sys="Linux", node="odetto", ...}) = 0
00:00:00.013412 brk(0) = 0x27e68
00:00:00.015731 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
00:00:00.033089 open("/home/QtPalmtop/lib/libqpe.so.1", O_RDONLY) = 3
00:00:00.035160 read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\330\20\4"..., 1024) = 1024
00:00:00.037930 fstat64(3, {st_mode=S_IFREG|0755, st_size=1496196, ...}) = 0
00:00:00.040184 old_mmap(NULL, 1526664, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x40020000
00:00:00.042307 mprotect(0x40183000, 72584, PROT_NONE) = 0
00:00:00.044091 old_mmap(0x40188000, 53248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x160000) = 0x40188000
00:00:00.046477 close(3) = 0
citytime の起動後、0.03 秒して libqpe.so.1 をロードし、その 0.013 秒後にクローズ。
72kB のファイルをロードするのに 0.01 秒しかかかってないことに注意。
もう少し後ろに libqte (4MB) のケースがあるが、こちらも消費時間は約 0.02 秒ほどだ。
... 中略 ...
00:00:00.164463 close(3) = 0
00:00:00.166579 open("/home/QtPalmtop/lib/libqte.so.2", O_RDONLY) = 3
00:00:00.168642 read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0@\317\f\000"..., 1024) = 1024
00:00:00.171062 fstat64(3, {st_mode=S_IFREG|0755, st_size=4126556, ...}) = 0
00:00:00.173264 old_mmap(NULL, 4156044, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x403e4000
00:00:00.175391 mprotect(0x407b3000, 162444, PROT_NONE) = 0
00:00:00.177185 old_mmap(0x407b4000, 151552, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x3c8000) = 0x407b4000
00:00:00.179663 old_mmap(0x407d9000, 6796, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x407d9000
00:00:00.181912 close(3) = 0
00:00:00.184710 mprotect(0x403e4000, 3993600, PROT_READ|PROT_WRITE) = 0
00:00:00.946953 mprotect(0x403e4000, 3993600, PROT_READ|PROT_EXEC) = 0
00:00:00.951468 mprotect(0x40229000, 1323008, PROT_READ|PROT_WRITE) = 0
00:00:00.975282 mprotect(0x40229000, 1323008, PROT_READ|PROT_EXEC) = 0
00:00:00.978225 mprotect(0x40195000, 36864, PROT_READ|PROT_WRITE) = 0
00:00:00.988885 mprotect(0x40195000, 36864, PROT_READ|PROT_EXEC) = 0
00:00:00.990874 mprotect(0x40020000, 1454080, PROT_READ|PROT_WRITE) = 0
00:00:01.157151 mprotect(0x40020000, 1454080, PROT_READ|PROT_EXEC) = 0
00:00:01.165956 munmap(0x40019000, 8555) = 0
libqte など明示的にリンクされているやつを一通りロードしたあとで名前解決。
その名前解決だけで約 1 秒。これはしかも RTLD_LAZY モード
(名前解決をできるだけ後回しにする) であって、
RTLD_NOW (名前はここですべて解決してしまう) にすると消費時間は 2.6 秒に増える。
... と見てきたように書いてるが、
RTLD_LAZY, RTLD_NOW の比較のほうは自前で dlopen して比較してみたものの、
mprotect() の中身が名前解決だけだというのは
これだけでは分からない (分かるのかもしれないが、少なくとも私には読み取れない)。
mmap でファイル全体を張り付けてもファイル全体が実際に張り付いているとは限らないからだ。
linux i386 で strace すると
(どーやら objprelink によって)
ここの mprotect() の発行がなくなることから、
名前解決しかしてないということがみてとれる。
つーか、mprotect(PROT_EXEC)システムコールでこれほど時間がかかるというのは
それしか思いあたらん。
00:00:01.169600 brk(0) = 0x27e68
00:00:01.171438 brk(0x27e88) = 0x27e88
00:00:01.173233 brk(0x28000) = 0x28000
00:00:01.178356 brk(0x29000) = 0x29000
00:00:01.229528 gettimeofday({1039407852, 667668}, NULL) = 0
00:00:01.237872 mkdir("/tmp/qtembedded-unknown", 0700) = -1 EEXIST (File exists)
... 中略 ...
00:00:01.282760 brk(0x3b000) = 0x3b000
00:00:01.285183 write(3, "\25\0\0\0\20\0\0\0\20\0\0\0\0c\0i\0t\0y\0t\0i\0m\0e", 28) = 28
00:00:01.288709 select(4, [3], NULL, NULL, {2, 0}) = 1 (in [3], left {1, 990000})
... 中略 ...
00:00:01.326470 shmat(393228, 0, 0) = 0x407db000
00:00:01.330353 open("/dev/fb0", O_RDWR) = 4
00:00:01.332397 ioctl(4, 0x4602, 0xbffff6fc) = 0
00:00:01.334229 ioctl(4, 0x4600, 0xbffff65c) = 0
00:00:01.336419 old_mmap(NULL, 153600, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0) = 0x407e3000
00:00:01.340274 stat64("/tmp/qtembedded-unknown/QtEmbedded-0", {st_mode=S_IFSOCK|0600, st_size=0, ...}) = 0
00:00:01.342830 shmget(1913099482, 0, 0) = 425997
00:00:01.344611 shmat(425997, 0, SHM_RDONLY) = 0x40809000
00:00:01.349807 open("/home/QtPalmtop/lib/fonts/fontdir", O_RDONLY) = 5
00:00:01.353082 fstat64(5, {st_mode=S_IFREG|0644, st_size=2089, ...}) = 0
00:00:01.355215 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40019000
サーバに接続、自分の名前を送ってから /dev/fb を開く。
フレームバッファの調停でもやってんのかな。この間およそ 0.2 秒。
00:00:01.554388 open("/home/QtPalmtop/lib/libqsfepj.so", O_RDONLY) = 5
00:00:01.556497 read(5, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\260\337\0"..., 1024) = 1024
... 中略 ...
00:00:01.609378 close(5) = 0
00:00:01.618276 mprotect(0x40847000, 479232, PROT_READ|PROT_WRITE) = 0
00:00:01.757933 mprotect(0x40847000, 479232, PROT_READ|PROT_EXEC) = 0
00:00:01.759794 mprotect(0x4081a000, 143360, PROT_READ|PROT_WRITE) = 0
00:00:01.802020 mprotect(0x4081a000, 143360, PROT_READ|PROT_EXEC) = 0
A300 特有の libqsfepj, libsl, libkke など日本語関連のロード。
ファイルサイズは小さくても、0.3 秒かかって意外にバカにならない。
そしてようやく main() から
QPEApplication::QPEApplication(int argc, char** argv) の実行に入る。
00:00:01.811318 rt_sigaction(SIGSEGV, {0x40088618, [SEGV], SA_RESTART|0x4000000}, {SIG_DFL}, 8) = 0
00:00:01.816781 stat64(".", {st_mode=S_IFDIR|0755, st_size=2048, ...}) = 0
00:00:01.819257 getcwd("/home/QtPalmtop/bin", 4095) = 20
00:00:01.824373 getcwd("/home/QtPalmtop/bin", 4095) = 20
00:00:01.826728 chdir("/home/QtPalmtop/bin") = 0
00:00:01.828710 getcwd("/home/QtPalmtop/bin", 4095) = 20
00:00:01.831041 chdir("/home/QtPalmtop/bin") = 0
00:00:01.848870 access("/home/QtPalmtop//help/ja/html/citytime.html", F_OK) = 0
00:00:01.855224 access("/home/QtPalmtop//i18n/ja/citytime.qm", R_OK) = 0
00:00:01.857787 open("/home/QtPalmtop//i18n/ja/citytime.qm", O_RDONLY) = 5
00:00:01.860167 fstat64(5, {st_mode=S_IFREG|0644, st_size=44529, ...}) = 0
00:00:01.862420 old_mmap(NULL, 44529, PROT_READ, MAP_PRIVATE, 5, 0) = 0x40902000
00:00:01.864742 close(5) = 0
00:00:01.869112 access("/home/QtPalmtop//i18n/ja/libqpe.qm", R_OK) = 0
00:00:01.871582 open("/home/QtPalmtop//i18n/ja/libqpe.qm", O_RDONLY) = 5
00:00:01.873777 fstat64(5, {st_mode=S_IFREG|0644, st_size=32325, ...}) = 0
00:00:01.875916 old_mmap(NULL, 32325, PROT_READ, MAP_PRIVATE, 5, 0) = 0x4090d000
00:00:01.877997 close(5) = 0
00:00:01.882665 access("/home/root/Settings", F_OK) = 0
00:00:01.885189 lstat64("/home/root/Settings", {st_mode=S_IFDIR|0755, st_size=1024, ...}) = 0
00:00:01.888522 access("/home/root/Settings/qpe.conf", F_OK) = 0
00:00:01.891384 open("/home/root/Settings/qpe.conf", O_RDONLY) = 5
00:00:01.893676 fstat64(5, {st_mode=S_IFREG|0644, st_size=584, ...}) = 0
00:00:01.917779 fstat64(5, {st_mode=S_IFREG|0644, st_size=584, ...}) = 0
00:00:01.919898 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40019000
00:00:01.922104 read(5, "[Appearance]\nBackground = #FFFFF"..., 4096) = 584
00:00:01.983309 fstat64(5, {st_mode=S_IFREG|0644, st_size=584, ...}) = 0
00:00:01.985698 close(5) = 0
ヘルプファイルと generic な設定ファイル (qpe.conf) のロードに 0.1 秒。
ま、これはしょうがなかろ。このあたりから酷くなる。
00:00:01.987443 munmap(0x40019000, 4096) = 0
00:00:02.006270 ioctl(3, 0x541b, [28]) = 0
... 中略 ...
00:00:02.126725 semop(196614, 0xbffff5e4, 1) = 0
00:00:02.128630 semop(196614, 0xbffff5e4, 1) = 0
00:00:02.139798 open("/home/QtPalmtop/lib/fonts", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 5
00:00:02.141955 fstat64(5, {st_mode=S_IFDIR|0775, st_size=5120, ...}) = 0
00:00:02.144239 fcntl64(5, F_SETFD, FD_CLOEXEC) = 0
00:00:02.146648 pivot_root(umovestr: Input/output error
00:00:02.152315 lstat64("/home/QtPalmtop/lib/fonts/smoothtimes_170_50.qpf", {st_mode=S_IFREG|0444, st_size=17660, ...}) = 0
00:00:02.156161 lstat64("/home/QtPalmtop/lib/fonts/smoothtimes_100_50.qpf", {st_mode=S_IFREG|0444, st_size=8034, ...}) = 0
... 中略 ...
00:00:02.865315 readlink("/home/QtPalmtop/lib/fonts/lcfont_100_50.qpf", "/usr/QtPalmtop.rom/lib/fonts/lcfont_100_50.qpf", 4095) = 46
全フォントファイルをいちいち確認してまわっている。実に 0.7 秒。
00:00:02.869579 access("/tmp/.-nuv-nuy-nv1-nuu-nut-nvj-nw6-nto-ntn-ntn-nw6-nts-ntn", F_OK) = 0
00:00:02.872321 stat64("/tmp/.-nuv-nuy-nv1-nuu-nut-nvj-nw6-nto-ntn-ntn-nw6-nts-ntn", {st_mode=S_IFREG|0644, st_size=202884, ...}) = 0
00:00:02.875257 open("/tmp/.-nuv-nuy-nv1-nuu-nut-nvj-nw6-nto-ntn-ntn-nw6-nts-ntn", O_RDONLY) = 5
00:00:02.877379 fstat64(5, {st_mode=S_IFREG|0644, st_size=202884, ...}) = 0
00:00:02.879488 old_mmap(NULL, 202884, PROT_READ, MAP_SHARED, 5, 0) = 0x40915000
00:00:02.881655 close(5) = 0
00:00:02.894427 brk(0x42000) = 0x42000
... 中略 ...
00:00:03.599820 semop(196614, 0xbffff55c, 1) = 0
00:00:03.601704 semop(196614, 0xbffff55c, 1) = 0
これが何のチャネルなのか分からない ... しかもなんか 0.8 秒も消費してるぅ。
次は citytime 固有の設定ファイル群の読み込み。
00:00:03.608201 gettimeofday({1039407855, 46254}, NULL) = 0
00:00:03.610620 open("/etc/localtime", O_RDONLY) = 5
00:00:03.612972 fstat64(5, {st_mode=S_IFREG|0644, st_size=73, ...}) = 0
00:00:03.615084 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40019000
... 中略 ...
00:00:03.639405 gettimeofday({1039407855, 77453}, NULL) = 0
00:00:03.646014 brk(0x61000) = 0x61000
00:00:03.654694 gettimeofday({1039407855, 92741}, NULL) = 0
00:00:03.672362 brk(0x62000) = 0x62000
00:00:03.677550 gettimeofday({1039407855, 115591}, NULL) = 0
00:00:03.680283 open("/usr/share/zoneinfo/zone.tab", O_RDONLY) = 5
00:00:03.682727 fstat64(5, {st_mode=S_IFREG|0644, st_size=17030, ...}) = 0
00:00:03.686579 open("/home/QtPalmtop/zone/cityinfo", O_RDONLY) = 6
... 中略 ...
00:00:05.013962 brk(0x6d000) = 0x6d000
00:00:05.084973 fstat64(6, {st_mode=S_IFREG|0644, st_size=10690, ...}) = 0
00:00:05.087358 close(6) = 0
00:00:05.089113 munmap(0x40019000, 4096) = 0
00:00:05.091339 fstat64(5, {st_mode=S_IFREG|0644, st_size=17030, ...}) = 0
00:00:05.093461 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40019000
00:00:05.095559 read(5, "# @(#)zone.tab\t1.25\n#\n# TZ zone "..., 4096) = 4096
... 中略 ...
00:00:06.882442 close(5) = 0
localtime, zone.tab, cityinfo を読み込むのに 3.2 秒。なんかそろそろ腹立ってくるが ──
00:00:06.884189 munmap(0x40019000, 4096) = 0
00:00:06.971773 access("/home/root/Settings", F_OK) = 0
00:00:06.974008 lstat64("/home/root/Settings", {st_mode=S_IFDIR|0755, st_size=1024, ...}) = 0
00:00:06.976928 access("/home/root/Settings/qpe.conf", F_OK) = 0
00:00:06.979408 open("/home/root/Settings/qpe.conf", O_RDONLY) = 5
... 中略 ...
00:00:07.051404 close(5) = 0
一回読んだはずの qpe.conf をまた読んで、しかも 0.2 秒もかかってるって何やねん。
00:00:07.053152 munmap(0x40019000, 4096) = 0
... 中略 ...
00:00:07.098347 open("/home/root/Settings/CityTime.conf", O_RDONLY) = 5
... 中略 ...
00:00:07.142972 close(5) = 0
CityTime.conf 読むのに 0.07 秒。これはまあ構わない。
00:00:07.144717 munmap(0x40019000, 4096) = 0
00:00:07.160482 semop(196614, 0xbffff668, 1) = 0
00:00:07.162450 semop(196614, 0xbffff668, 1) = 0
... 中略 ...
00:00:07.831586 semop(196614, 0xbffff524, 1) = 0
00:00:07.833381 semop(196614, 0xbffff524, 1) = 0
えーと、やっぱ調べなきゃならんか? この semop() (semaphore operetion) が何やってるか。
0.7 秒も誰の何を待ってんだろ。それはともかく次は健忘症第二段。
00:00:07.841357 access("/home/QtPalmtop/zone/cityinfo", F_OK) = 0
00:00:07.844042 open("/home/QtPalmtop/zone/cityinfo", O_RDONLY) = 5
... 中略 ...
00:00:09.159252 brk(0x95000) = 0x95000
00:00:09.172377 fstat64(5, {st_mode=S_IFREG|0644, st_size=10690, ...}) = 0
00:00:09.174640 close(5) = 0
ほほぅ(-_-# cityinfo の読み直しで 1.3 秒。ほー ... (-_-####
00:00:09.176390 munmap(0x40019000, 4096) = 0
00:00:09.184877 brk(0x96000) = 0x96000
00:00:09.188101 semop(196614, 0xbffff6d8, 1) = 0
... 中略 ...
00:00:09.671122 semop(196614, 0xbffff5ac, 1) = 0
00:00:09.681678 brk(0x97000) = 0x97000
00:00:09.687825 access("/home/root/Settings", F_OK) = 0
00:00:09.690027 lstat64("/home/root/Settings", {st_mode=S_IFDIR|0755, st_size=1024, ...}) = 0
00:00:09.693003 access("/home/root/Settings/qpe.conf", F_OK) = 0
00:00:09.695435 open("/home/root/Settings/qpe.conf", O_RDONLY) = 5
... 中略 ...
00:00:09.765167 fstat64(5, {st_mode=S_IFREG|0644, st_size=584, ...}) = 0
00:00:09.767355 close(5) = 0
もっとも健忘症第三段のほうは 0.07 秒だから症状は軽い。
ここから表示 routine っつーか、citytime の中身に入る。
00:00:09.769082 munmap(0x40019000, 4096) = 0
00:00:09.773869 time([1039407861]) = 1039407861
00:00:09.775863 open("/usr/share/zoneinfo/Asia/Tokyo", O_RDONLY) = 5
00:00:09.778049 fstat64(5, {st_mode=S_IFREG|0644, st_size=73, ...}) = 0
... 中略 ...
00:00:10.503377 munmap(0x40996000, 151552) = 0
00:00:10.567906 ioctl(3, 0x541b, [0]) = 0
00:00:10.570066 write(3, "\22\0\0\0\10\0\0\0\300\367\377\277QPE/Fep\0\22\0\0\0\v"..., 503) = 503
00:00:10.572838 select(4, [3], NULL, NULL, {1, 0}) = 1 (in [3], left {0, 840000})
初期表示に 0.8 秒。入力のための select() で起動を終える。以上、10.5 秒の大長編でした。
citytime のバカさ加減の象徴の 6.0 秒はともかく、名前解決や QPEApplication の初期化に それぞれ 1-2 秒ずつ取られるのはけっこう痛い。これはソフトの造りでどうにかなる部分ではないからだ。
1.2 秒 ライブラリのロードから名前解決まで。 0.2 秒 /dev/fb を開く 1.8 秒 QPEApplication 初期化 6.0 秒 設定&データファイルの読み込み 0.8 秒 初期表示
この方法で解決できるのはライブラリの名前解決までで、したがって 1 秒強かせげるだけである。 匿名さんのテストの結果もほぼこれに沿っているようだ。
その QPEApplication(int argc, char** argv) は qtopia-free のソースを読むかぎり引数に (0, NULL) を渡すことが出来る。 これは実際に (0, NULL) を渡すケースがあるかどうかはともかく、 渡してもアプリの実行には致命的でないということをあらわす。
てわけで、constructor には何も渡さず、QPEApplication::setArgs(int argc, char** argv) で名前を設定した (さすがに名前を設定しとかんと config file を読みこめんだろう、たぶん) textedit をつくってみたら動いた:
int main( int argc, char **argv )
{
static int t_argc = 0;
static char* dummy[1];
dummy[0] = NULL;
QPEApplication a( t_argc, dummy );
a.setArgs( argc, argv );
TextEdit e;
a.showMainDocumentWidget(&e);
if ( argc == 3 && argv[1] == QCString("-f") )
e.openFile(argv[2]);
a.exec();
}
これで動くんなら QPEApplication::QPEApplication(int argc, char** argv)
の起動直後で待つことができる。おーむね 3 秒ほど稼げる計算だが、
サーバとのチャネルを同じ名前で持つことになるんで、重複起動するとどっかヘタると思う ...
でもこれで動くんなら、名前なし用の constructor をちゃんと書いてやれば待てるということではある。
% LD_DEBUG=statistics qvfb 00312: number of relocations: 8478 00312: number of relocations from cache: 1300121479 シンボル中 13001 が解決済みだと。
# LD_DEBUG=statistics textedit 10697: number of relocations: 19833 10697: number of relocations from cache: 211入ってるにゃ入ってるが、ほとんど役にたっとらんよーである。 まあ i386 向けと明記されてれるよーな機構だし。
標準アプリにほとんど手を加えないなら、quickexec などの高速化機構ではどーせ不足する。 10 秒が 7 秒になったからといって使いモンになるわけではない。 人が PDA で待てるのは 1 秒がとこだろうから、事実上、 高速起動モードしか選択肢はない。
ファイルの読み込みそのものに時間を食ってるわけではないから、 swapout してしまっても時間的な問題ないと思う (んだか、だれか比較チェックしてくれ ...)。
いまんとこ、swap を大きくもっておいて、 かたっぱしから高速起動モードってのが唯一の解になるんではなかろーか。