Open2023/10/18にコメント追加4

WasmLinux: タイマー挙動がおかしい問題

とりあえずいろいろ修正してsyscallが発行できそうな状態までは持っていくことができた。

... が、なんか起動に70秒とか掛かる。CPUはほぼ消費していない状態でコレなので、タイマの挙動がもっとも怪しい。

`ULONG_MAX` ナノ秒のタイマを設定している

backtraceを観察すると、 w2c_lin_tick_program_event(instance=0x00007ffdf0000b70, var_p0=5280000000, var_p1=1) → w2c_lin_clockevents_program_event(instance=0x00007ffdf0000b70, var_p0=1303680, var_p1=4294967295, var_p2=1) の呼出しがある。この tick_program_eventの呼出しは 5280000000 ナノ秒は約5秒で、これ自体は妥当に見える。これを32bitに丸めると ULONG_MAX (0xffffffff)になる。

(wasm2c出力は自身の関数の引数を普通に書き換えてくるので、backtrace中の引数は破壊されている可能性が常にある。ただし、今回のケースは大丈夫っぽい。)

既にタイマーが設定されているのに tick_nohz_idle_stop_tick しているのが問題。。？

Oneshot timer: 8 4294967295
Process 58324 stopped
* thread #2, name = 'runner', stop reason = signal SIGABRT
    frame #0: 0x00007ffff7ab0884 libc.so.6`__pthread_kill_implementation + 276
libc.so.6`__pthread_kill_implementation:
->  0x7ffff7ab0884 <+276>: movl   %eax, %ebx
    0x7ffff7ab0886 <+278>: negl   %ebx
    0x7ffff7ab0888 <+280>: cmpl   $0xfffff000, %eax         ; imm = 0xFFFFF000
    0x7ffff7ab088d <+285>: movl   $0x0, %eax
(lldb) bt
* thread #2, name = 'runner', stop reason = signal SIGABRT
  * frame #0: 0x00007ffff7ab0884 libc.so.6`__pthread_kill_implementation + 276
    frame #1: 0x00007ffff7a5fafe libc.so.6`raise + 30
    frame #2: 0x00007ffff7a4887f libc.so.6`abort + 223
    frame #3: 0x0000000002032d03 runner`mod_timer(in=0x00007ffe37c42068, out=0x00007ffe37c42058) at runner.cpp:543:22
    frame #4: 0x0000000002032f35 runner`w2c_env_nccc_call64(env=0x0000000000000000, inptr=1075970144, outptr=1075970136) at runner.cpp:602:22
    frame #5: 0x000000000108b0a0 runner`w2c_lin_host_timer_set_oneshot(instance=0x00007ffdf0000b70, var_p0=8, var_p1=4294967295) at lin.c:1401301
    frame #6: 0x0000000000bf1105 runner`w2c_lin_clockevent_next_event(instance=0x00007ffdf0000b70, var_p0=4294967295, var_p1=1303680) at lin.c:936982
    frame #7: 0x0000000000bed63c runner`w2c_lin_clockevents_program_event(instance=0x00007ffdf0000b70, var_p0=1303680, var_p1=4294967295, var_p2=1) at lin.c:935777
    frame #8: 0x0000000000d7d290 runner`w2c_lin_tick_program_event(instance=0x00007ffdf0000b70, var_p0=5280000000, var_p1=1) at lin.c:1092569
    frame #9: 0x0000000000e870e0 runner`w2c_lin_hrtimer_start_range_ns(instance=0x00007ffdf0000b70, var_p0=1316480, var_p1=5280000000, var_p2=0, var_p3=1) at lin.c:1196460
    frame #10: 0x0000000000d86021 runner`w2c_lin_tick_nohz_idle_stop_tick(instance=0x00007ffdf0000b70) at lin.c:1096049
    frame #11: 0x0000000001072b24 runner`w2c_lin_do_idle(instance=0x00007ffdf0000b70) at lin.c:1391780
    frame #12: 0x0000000001072e4d runner`w2c_lin_cpu_startup_entry(instance=0x00007ffdf0000b70, var_p0=236) at lin.c:1391866
    frame #13: 0x0000000000f3c1fd runner`w2c_lin_rest_init(instance=0x00007ffdf0000b70) at lin.c:1267980
    frame #14: 0x0000000000f3d496 runner`w2c_lin_arch_call_rest_init(instance=0x00007ffdf0000b70) at lin.c:1268471
    frame #15: 0x0000000000f3dd7c runner`w2c_lin_start_kernel(instance=0x00007ffdf0000b70) at lin.c:1268646
    frame #16: 0x00000000010685b8 runner`w2c_lin_lkl_run_kernel(instance=0x00007ffdf0000b70, var_p0=0) at lin.c:1388611
    frame #17: 0x00000000020322a9 runner`thr_trampoline(objid=6) at runner.cpp:290:16
    frame #18: 0x0000000002034ad5 runner`unsigned long std::__invoke_impl<unsigned long, unsigned long (*)(int), int>((null)=__invoke_other @ 0x00007ffdf7a20b10, __f=0x0000000002344940, (null)=0x0000000002344938) at invoke.h:61:36
    frame #19: 0x00000000020349ec runner`std::__invoke_result<unsigned long (*)(int), int>::type std::__invoke<unsigned long (*)(int), int>(__fn=0x0000000002344940, (null)=0x0000000002344938) at invoke.h:96:40
    frame #20: 0x00000000020348cd runner`unsigned long std::thread::_Invoker<std::tuple<unsigned long (*)(int), int>>::_M_invoke<0ul, 1ul>(this=0x0000000002344938, (null)=_Index_tuple<0, 1> @ 0x00007ffdf7a20b70) at std_thread.h:292:26
    frame #21: 0x000000000203483e runner`std::thread::_Invoker<std::tuple<unsigned long (*)(int), int>>::operator()(this=0x0000000002344938) at std_thread.h:299:20
    frame #22: 0x0000000002034806 runner`std::thread::_State_impl<std::thread::_Invoker<std::tuple<unsigned long (*)(int), int>>>::_M_run(this=0x0000000002344930) at std_thread.h:244:20
    frame #23: 0x00007ffff7ce31f3 libstdc++.so.6`execute_native_thread_routine + 19
    frame #24: 0x00007ffff7aae947 libc.so.6`start_thread + 759
    frame #25: 0x00007ffff7b34860 libc.so.6`__clone3 + 48

okuoku

手動でstepすると高速に完了する

b w2c_lin_tick_nohz_stop_tick で tick_nohz_stop_tick にブレークポイントを張って手で1つ1つcontinueしていくと、普通に実行した場合よりも高速に実行完了する。たぶんこの状態が正常なのだろう。

[   53.373068] Run /init as init process

... つまり、タイマの精度を劣化させると正常になると言える。デバッグ中にもタイマは容赦なく進むので。。実際、タイマを再設定したときにwait中だったらタイマを発火させるように変更したら正常に動作した。

割り込みがおかしい。。？

okuoku

全然わからん

ちょっと後まわしで。。

問題は tick_nohz_idle_stop_tick で既に他で設定しているoneshotタイマを上書きしてしまうこと。で、問題は設定値が ULONG_MAX に達したときに起こる。

oneshotタイマは long を受けとり、これはカーネル内の ktime_t とは長さが異なるため、その辺で比較が狂ってしまうんだろうか。。でもLinuxはまだ32bitアーキテクチャをサポートしているのでこれが大きな問題になるとは考えづらい。。

ワークアラウンドは、そもそもnohzなtickを止めるときに問題が発生するので、放置するようにした。

これで、 0.5 秒でカーネルが起動するようになった。

[    0.552826] Run /init as init process

ULONG_MAX ナノ秒のタイマを設定している

手動でstepすると高速に完了する

全然わからん

`ULONG_MAX` ナノ秒のタイマを設定している