::log.2015
[ TOP | Recently ]
ESP8266 lwip / NetBSD/arm の printf が遅い。
2015-10-01 ESP8266 lwip
最近ESP8266をいじってます。Arduinoは中で何やってるかよくわからなくてｷﾓﾁﾜﾙｲので、xtensa--gccを使ってC言語です。
なので必然的にespressifが出してるsdkを使うのですが、このsdkがいまいちイケてない…
まず、WiFiやらに繋げるコードを書いてみると、シリアルに意図しない出力が。
どうもsdk libraryの中でprintfしてくれちゃってるようです。勝手にprintfしないでよ。
調べたら system_set_os_print(0) としておけば sdk library の中で printf するのを抑制できるらしいので、入れてみる。
すると今度は user program からの printf (os_printf()) も何も出力しなくなった。おいｗ
つーかーえーねーーーーーーーー(1つめ)
幸いシリアルのI/O portを直接ドライブするサンプルコードがあったので、オレオレprintfを入れてしまうことで対処。なんだかなあ。
もう一つは、TCPが不安定。telnetでつないで各種ルータやunixマシンのシリアルコンソールに繋げるものを作ったんだけど、
大量に送受信しているとTCPが切れる。tcpdumpで見てみると、ずいぶん変な切れ方をしている。
ESP8266側がtimeoutで切れた時にTCP_RSTを送るのだが、TCPのseqが狂っている。
そのためcilentは無視するので何度も再送ackを送る。ESPは何度もRSTを返す、みたいなことになっている。
糞IPスタックじゃねーか。(2つめ)
そもそもなんで切れるんだよTCPだろ再送しろよと思って調べてたらESP8266のsdkに使われてるlwipのソースがあった http://bbs.espressif.com/viewtopic.php?f=46&t=951 ので
これでliblwipを作りなおしてdebugできるぜと張り切ってデバッグしてみると、切断直前の数秒間にESP側でTCPの再送が走ってる。しかしtcpdumpして見ててもESP側から再送ackを送ってるようには見えない。
やっぱり糞IPスタックじゃねーか。
というわけでちまちまデバッグしてたら、追いかけてった先に #if 1 /* by Snake: resolve the bug of pbuf reuse */ 〜 #endif みたいな修正個所が。
本家 lwip には無い修正で、これのせいじゃねーの？ と思って #if 0 にしたらTCP切れる問題は綺麗になおった。
どうも espressif でコメントの内容の事を修正しようとしたがエンバグしちゃったんだろうなぁ。リポジトリ公開してくれてないから経緯がよくわかんないけど。
とりあえず #if 0 にしてもメモリリークとかは起きてない様子なので問題なさげ。
なんで俺はsdkのデバッグをしてるんだろう。
なので必然的にespressifが出してるsdkを使うのですが、このsdkがいまいちイケてない…
まず、WiFiやらに繋げるコードを書いてみると、シリアルに意図しない出力が。
どうもsdk libraryの中でprintfしてくれちゃってるようです。勝手にprintfしないでよ。
調べたら system_set_os_print(0) としておけば sdk library の中で printf するのを抑制できるらしいので、入れてみる。
すると今度は user program からの printf (os_printf()) も何も出力しなくなった。おいｗ
つーかーえーねーーーーーーーー(1つめ)
幸いシリアルのI/O portを直接ドライブするサンプルコードがあったので、オレオレprintfを入れてしまうことで対処。なんだかなあ。
もう一つは、TCPが不安定。telnetでつないで各種ルータやunixマシンのシリアルコンソールに繋げるものを作ったんだけど、
大量に送受信しているとTCPが切れる。tcpdumpで見てみると、ずいぶん変な切れ方をしている。
ESP8266側がtimeoutで切れた時にTCP_RSTを送るのだが、TCPのseqが狂っている。
そのためcilentは無視するので何度も再送ackを送る。ESPは何度もRSTを返す、みたいなことになっている。
糞IPスタックじゃねーか。(2つめ)
そもそもなんで切れるんだよTCPだろ再送しろよと思って調べてたらESP8266のsdkに使われてるlwipのソースがあった http://bbs.espressif.com/viewtopic.php?f=46&t=951 ので
これでliblwipを作りなおしてdebugできるぜと張り切ってデバッグしてみると、切断直前の数秒間にESP側でTCPの再送が走ってる。しかしtcpdumpして見ててもESP側から再送ackを送ってるようには見えない。
やっぱり糞IPスタックじゃねーか。
というわけでちまちまデバッグしてたら、追いかけてった先に #if 1 /* by Snake: resolve the bug of pbuf reuse */ 〜 #endif みたいな修正個所が。
本家 lwip には無い修正で、これのせいじゃねーの？ と思って #if 0 にしたらTCP切れる問題は綺麗になおった。
どうも espressif でコメントの内容の事を修正しようとしたがエンバグしちゃったんだろうなぁ。リポジトリ公開してくれてないから経緯がよくわかんないけど。
とりあえず #if 0 にしてもメモリリークとかは起きてない様子なので問題なさげ。
なんで俺はsdkのデバッグをしてるんだろう。
2015-07-09 NetBSD/arm の printf が遅い。
NetBSD/arm で、long long を printf "%llu" ("%lld") で表示するスピードが尋常じゃない遅さなのに気づいた。
ちなみにどれくらい遅いかというと、sprintf("%lld") は sprintf("%d") の20倍くらい遅い。2倍じゃないぞ。20倍だ。
追いかけてみると、10進数に変換する部分、10の商と剰余を毎桁計算して
としている個所がメチャ遅い様子。そう、armには割り算が無い。(Cortex-A15から存在する)
そもそも定数割り算の場合はコンパイラがよきにはからって乗算とシフトに展開してくれるのではないか？
…と思ってgccを調べたら、乗算+シフトに展開してくれるのは32bit除算の時だけで、64bit除算の場合gccはlibgccのudivdi3()を呼んでいた。(gcc/arm)
じゃあudivdi3が遅いのではないか？ よく使う除数は内部で場合分けしてて、乗算+シフトで計算してくれても良さそうだが、と思ってこれまた調べたら、そういうものもない様子。
それならそれでいいんだけど、じゃあ64bit除算も乗算+シフトに展開してくれよんgcc！ とか思った。これじゃ片手落ちだ。
まぁgccがそういう実装なのはしょうがないので置いとくとして、これを速くしてやろうと思う。
そもそも乗算+シフトで除算をするにはどうしたらいいか。
32bitの値を10で割る場合、0xCCCCCCCDを掛けてから35ビット右シフトすればよい。
0xCCCCCCCD てなんじゃらほい？ と思った人のために説明すると、0xCCCCCCCD は10進で3435973837、35ビット右シフトは1/2^35で1/34359738368であるので、
3435973837/34359738368 = 0.10000000000582076609134674072265625 = 0.1 = 1/10
となる。
つまり (2^n/10) に近い値を掛けて、nビット右シフトしてやればいいのだ。
3倍して右5bitシフト(1/32)してもいいし、102倍して右10ビットシフト(1/1024)してもいいのだが、当然誤差がでてしまうので、32bitに収まるうちのギリギリの数が0xCCCCCCCDというわけだ。
64bitの場合は、2^67/10に近い 0xCCCCCCCCCCCCCCCD を掛けて、67ビット右シフトする。
同様に説明すると、0xCCCCCCCCCCCCCCCD は 14757395258967641293、67ビット右シフトは 2^67 = 147573952589676412928 なので、
14757395258967641293 / 147573952589676412928 = 0.1000000000000000000013552527156068805425093160010874271392822265625 = 0.1 = 1/10
となる。
uint64_t を 10 で割る所を上の乗算+シフトに書き換えれば速くなるに違いないというわけで、書いてみた。
ベンチマークは以下の通り。
sprintf … 素のprintf
str_uint64_div … 中身はsprintfの実装をシンプルにしたもの
str_uint64_nodiv … 上の乗算+シフトで実装したもの
というわけで15倍くらいになった。
処理内容がほぼ同はずのsprintfとstr_uint64_divの8%の差は、libcのsprintf()には桁合わせとか色々余計な処理があるためのオーバーヘッドと測定誤差と思われる。
ちなみにLinux(glibc)はどうなんだと思って調べたら、glibcはちゃんと乗算+シフトを使っていた。NetBSDダメじゃん…
さて、libcのsprintfの方も修正すればとりあえず解決なのだが、他にもっと速い方法は無いものかと、思いついたものを試してみた。
・上の桁から引き算していく方法
64bitを10進にする場合、0xFFFFFFFFFFFFFFFF = 18446744073709551615 なので最大20桁。ならば
10^20、10^19…と順に桁毎に引き算していき、引けた数を表示すれば10進になるよね、というわけで書いてみた。
各桁でループしてるから遅いかな、と思ったが、これがなかなか速い。
乗算+シフトよりも2割ほど速くなった。しかし引ける数でループしてるので、999999999 みたいな数だとループの回数が多くなるので遅くなる(それでも速いが)。
そこでループを展開してみた。何も考えず展開するのではなくて、桁の値が8未満なら4以上か4未満か、4未満なら2以上か2未満か…のように二分探索で展開する。
これはかなり効いたようだ。
最初の除算から比べると36倍。乗算+シフトと比較しても2倍以上だ。コードサイズが7〜8kbyteになるが ;)
ベンチマークプログラムはgithubに置いておく。https://github.com/ryo/lltoa
というわけでオレオレNetBSD/armにはnodiv_noloop版を入れることにした。
本家netbsdにも少くともsprintf遅杉という問題提起はしなきゃですね。
ちなみにどれくらい遅いかというと、sprintf("%lld") は sprintf("%d") の20倍くらい遅い。2倍じゃないぞ。20倍だ。
追いかけてみると、10進数に変換する部分、10の商と剰余を毎桁計算して
do {
*--dst = (n % 10) + '0';
n /= 10;
} while (n != 0);
としている個所がメチャ遅い様子。そう、armには割り算が無い。(Cortex-A15から存在する)
そもそも定数割り算の場合はコンパイラがよきにはからって乗算とシフトに展開してくれるのではないか？
…と思ってgccを調べたら、乗算+シフトに展開してくれるのは32bit除算の時だけで、64bit除算の場合gccはlibgccのudivdi3()を呼んでいた。(gcc/arm)
じゃあudivdi3が遅いのではないか？ よく使う除数は内部で場合分けしてて、乗算+シフトで計算してくれても良さそうだが、と思ってこれまた調べたら、そういうものもない様子。
それならそれでいいんだけど、じゃあ64bit除算も乗算+シフトに展開してくれよんgcc！ とか思った。これじゃ片手落ちだ。
まぁgccがそういう実装なのはしょうがないので置いとくとして、これを速くしてやろうと思う。
そもそも乗算+シフトで除算をするにはどうしたらいいか。
32bitの値を10で割る場合、0xCCCCCCCDを掛けてから35ビット右シフトすればよい。
0xCCCCCCCD てなんじゃらほい？ と思った人のために説明すると、0xCCCCCCCD は10進で3435973837、35ビット右シフトは1/2^35で1/34359738368であるので、
3435973837/34359738368 = 0.10000000000582076609134674072265625 = 0.1 = 1/10
となる。
つまり (2^n/10) に近い値を掛けて、nビット右シフトしてやればいいのだ。
3倍して右5bitシフト(1/32)してもいいし、102倍して右10ビットシフト(1/1024)してもいいのだが、当然誤差がでてしまうので、32bitに収まるうちのギリギリの数が0xCCCCCCCDというわけだ。
64bitの場合は、2^67/10に近い 0xCCCCCCCCCCCCCCCD を掛けて、67ビット右シフトする。
同様に説明すると、0xCCCCCCCCCCCCCCCD は 14757395258967641293、67ビット右シフトは 2^67 = 147573952589676412928 なので、
14757395258967641293 / 147573952589676412928 = 0.1000000000000000000013552527156068805425093160010874271392822265625 = 0.1 = 1/10
となる。
uint64_t を 10 で割る所を上の乗算+シフトに書き換えれば速くなるに違いないというわけで、書いてみた。
static inline uint64_t
lldiv10(uint64_t x)
{
#define MAGIC10_H 0xcccccccc
#define MAGIC10_L 0xcccccccd
#define MAGIC10_SHIFT 3
uint64_t xh = x >> 32;
uint64_t xl = x & 0xffffffff;
uint64_t a = xh * MAGIC10_L;
uint64_t ah = a >> 32;
uint64_t al = a & 0xffffffff;
uint64_t b = xl * MAGIC10_H;;
uint64_t bh = b >> 32;
uint64_t bl = b & 0xffffffff;
return (((((xl * MAGIC10_L) >> 32) + al + bl) >> 32) + ah + bh + xh * MAGIC10_H) >> MAGIC10_SHIFT;
}
char *
str_uint64_mulshift(char *dst, uint64_t n)
{
uint64_t q;
int l;
char *p, *p0;
p = p0 = dst + 20; /* 20 = maximum length of decimal UINT64_MAX */
do {
q = lldiv10(n);
*--p = (n - (q * 10)) + '0';
n = q;
} while (n != 0);
l = p0 - p;
memmove(dst, p, l);
dst[l] = '\0';
return &dst[l];
}
char *
str_uint64_div(char *dst, uint64_t n)
{
int l;
char *p, *q;
p = q = dst + 20; /* 20 = maximum length of decimal UINT64_MAX */
do {
*--p = (n % 10) + '0';
n /= 10;
} while (n != 0);
l = q - p;
memmove(dst, p, l);
dst[l] = '\0';
return &dst[l];
}
ベンチマークは以下の通り。
sprintf … 素のprintf
str_uint64_div … 中身はsprintfの実装をシンプルにしたもの
str_uint64_nodiv … 上の乗算+シフトで実装したもの
try 10000 loops for each functions ---------------------------------------------------------------------------- sprintf 6.416028455 sec, 1558.59658 times/sec, 100.00% str_uint64_div 5.933064350 sec, 1685.46967 times/sec, 108.14% str_uint64_mulshift 0.372681510 sec, 26832.56274 times/sec, 1702.15%
というわけで15倍くらいになった。
処理内容がほぼ同はずのsprintfとstr_uint64_divの8%の差は、libcのsprintf()には桁合わせとか色々余計な処理があるためのオーバーヘッドと測定誤差と思われる。
ちなみにLinux(glibc)はどうなんだと思って調べたら、glibcはちゃんと乗算+シフトを使っていた。NetBSDダメじゃん…
さて、libcのsprintfの方も修正すればとりあえず解決なのだが、他にもっと速い方法は無いものかと、思いついたものを試してみた。
・上の桁から引き算していく方法
64bitを10進にする場合、0xFFFFFFFFFFFFFFFF = 18446744073709551615 なので最大20桁。ならば
10^20、10^19…と順に桁毎に引き算していき、引けた数を表示すれば10進になるよね、というわけで書いてみた。
char *
str_uint64_nodiv(char *dst, uint64_t n)
{
char *p = dst;
int q;
int pad = 0;
/*
* uint64_t の最大は 18446744073709551615 なので
* 一番上の桁は0か1しかない
*/
if (n >= 10000000000000000000ULL) {
*p++ = '1';
n -= 10000000000000000000ULL;
pad = 1;
}
#define QOUTPUT(X) \
if (n >= X) { \
q = 0; \
do { \
q++; \
n -= X; \
} while (n >= X); \
*p++ = q + '0'; \
pad = 1; \
} else if (pad) { \
*p++ = '0'; \
}
QOUTPUT(1000000000000000000ULL);
QOUTPUT(100000000000000000ULL);
QOUTPUT(10000000000000000ULL);
QOUTPUT(1000000000000000ULL);
QOUTPUT(100000000000000ULL);
QOUTPUT(10000000000000ULL);
QOUTPUT(1000000000000ULL);
QOUTPUT(100000000000ULL);
QOUTPUT(10000000000ULL);
QOUTPUT(1000000000ULL);
QOUTPUT(100000000ULL);
QOUTPUT(10000000ULL);
QOUTPUT(1000000ULL);
QOUTPUT(100000ULL);
QOUTPUT(10000ULL);
QOUTPUT(1000ULL);
QOUTPUT(100ULL);
QOUTPUT(10ULL);
*p++ = n + '0';
*p = '\0';
return p;
}
各桁でループしてるから遅いかな、と思ったが、これがなかなか速い。
try 10000 loops for each functions ------------------------------- str_uint64_div 6.248697894 sec, 1600.33341 times/sec, 100.00% str_uint64_mulshift 0.372665050 sec, 26833.74789 times/sec, 1676.75% str_uint64_nodiv 0.307277311 sec, 32543.89323 times/sec, 2033.56%
乗算+シフトよりも2割ほど速くなった。しかし引ける数でループしてるので、999999999 みたいな数だとループの回数が多くなるので遅くなる(それでも速いが)。
そこでループを展開してみた。何も考えず展開するのではなくて、桁の値が8未満なら4以上か4未満か、4未満なら2以上か2未満か…のように二分探索で展開する。
char *
str_uint64_nodiv_noloop(char *dst, uint64_t n)
{
char *p = dst;
int q;
int pad = 0;
/*
* uint64_t の最大は 18446744073709551615 なので
* 一番上の桁は0か1しかない
*/
if (n >= 10000000000000000000ULL) {
*p++ = '1';
n -= 10000000000000000000ULL;
pad = 1;
}
#define QXOUTPUT(X) \
if (n < ((X) * 8)) { \
if (n < ((X) * 4)) { \
if (n < ((X) * 2)) { \
if (n < (X)) { \
if (pad) \
*p++ = '0'; \
} else { \
*p++ = '1'; \
n -= (X); \
pad = 1; \
} \
} else { \
pad = 1; \
if (n < ((X) * 3)) { \
*p++ = '2'; \
n -= (X) * 2; \
} else { \
*p++ = '3'; \
n -= (X) * 3; \
} \
} \
} else { \
pad = 1; \
if (n < ((X) * 6)) { \
if (n < ((X) * 5)) { \
*p++ = '4'; \
n -= (X) * 4; \
} else { \
*p++ = '5'; \
n -= (X) * 5; \
} \
} else { \
if (n < ((X) * 7)) { \
*p++ = '6'; \
n -= (X) * 6; \
} else { \
*p++ = '7'; \
n -= (X) * 7; \
} \
} \
} \
} else { \
pad = 1; \
if (n < ((X) * 9)) { \
*p++ = '8'; \
n -= (X) * 8; \
} else { \
*p++ = '9'; \
n -= (X) * 9; \
} \
}
QXOUTPUT(1000000000000000000ULL);
QXOUTPUT(100000000000000000ULL);
QXOUTPUT(10000000000000000ULL);
QXOUTPUT(1000000000000000ULL);
QXOUTPUT(100000000000000ULL);
QXOUTPUT(10000000000000ULL);
QXOUTPUT(1000000000000ULL);
QXOUTPUT(100000000000ULL);
QXOUTPUT(10000000000ULL);
QXOUTPUT(1000000000ULL);
QXOUTPUT(100000000ULL);
QXOUTPUT(10000000ULL);
QXOUTPUT(1000000ULL);
QXOUTPUT(100000ULL);
QXOUTPUT(10000ULL);
QXOUTPUT(1000ULL);
QXOUTPUT(100ULL);
QXOUTPUT(10ULL);
*p++ = n + '0';
*p = '\0';
return p;
}
これはかなり効いたようだ。
try 100000 loops for each functions ------------------------------- str_uint64_div 59.452894663 sec, 1682.00389 times/sec, 100.00% str_uint64_mulshift 3.668981392 sec, 27255.52117 times/sec, 1620.41% str_uint64_nodiv 3.080811260 sec, 32458.98290 times/sec, 1929.78% str_uint64_nodiv_noloop 1.623337725 sec, 61601.47606 times/sec, 3662.38%
最初の除算から比べると36倍。乗算+シフトと比較しても2倍以上だ。コードサイズが7〜8kbyteになるが ;)
ベンチマークプログラムはgithubに置いておく。https://github.com/ryo/lltoa
というわけでオレオレNetBSD/armにはnodiv_noloop版を入れることにした。
本家netbsdにも少くともsprintf遅杉という問題提起はしなきゃですね。
EOF