[regression] profile: doesn't record userland functions

[X512]

This is hrev54291. Reproduced on both x86 and x86_64.

Steps to reproduce:

1. Run profile bash -c "while true; do true; done".
2. Press Ctrl+C.
3. Profile output will be empty.

Kernel functions are recorded.

[waddlesplash]

When did it last work?

[X512]

It seems to start working after reboot, strange...

[X512]

profile for userland functions is stop working after some time of use and recovered after reboot.

[X512]

On 32 bit profile for userland functions is not working at all. Reboot don't help.

profiling results for thread "w>TestApp" (2449):
  tick interval:  1000 us
  total ticks:    4043 (4043000 us)
  unknown ticks:  0 (0 us,   0.00%)
  dropped ticks:  0 (0 us,   0.00%)

        hits     unknown    image
  ------------------------------------------------------------------------------
        2695           0        1 kernel_x86

        hits       in us    in %   image  function
  ------------------------------------------------------------------------------
        1112     1112000   27.50       1  Wait__22ConditionVariableEntryUlx
         394      394000    9.75       1  handle_syscall
         235      235000    5.81       1  _Notify__17ConditionVariablebl
         182      182000    4.50       1  x86_sysenter
         167      167000    4.13       1  _mutex_lock
         126      126000    3.12       1  get_locked_port__Fl
         122      122000    3.02       1  _mutex_unlock
          68       68000    1.68       1  atomic_add
          43       43000    1.06       1  object_depot_obtain
          38       38000    0.94       1  _arch_cpu_user_memcpy
          28       28000    0.69       1  _user_read_port_etc
          25       25000    0.62       1  object_depot_store
          24       24000    0.59       1  Add__17ConditionVariableP22ConditionVariableEntry
          18       18000    0.45       1  writev_port_etc
          16       16000    0.40       1  read_port_etc
          16       16000    0.40       1  put_port_message__FPQ246_GLOBAL_.N..._src_system_kernel_port.cpp5DnjRa12port_message
          10       10000    0.25       1  AcquireReference__14BReferenceable
          10       10000    0.25       1  get_port_message__FlUlUlxPPQ246_GLOBAL_.N..._src_system_kernel_port.cpp5DnjRa12port_messageRQ246_GLOBAL_.N..._src_system_kernel_port.cpp5DnjRa4Port
           8        8000    0.20       1  _user_write_port_etc
           8        8000    0.20       1  user_memcpy
           7        7000    0.17       1  ReleaseReference__14BReferenceable
           6        6000    0.15       1  object_cache_alloc
           6        6000    0.15       1  _get_port_message_info_etc
           4        4000    0.10       1  port_count
           3        3000    0.07       1  notify_port_select_events__FPQ246_GLOBAL_.N..._src_system_kernel_port.cpp5DnjRa4PortUs
           3        3000    0.07       1  port_buffer_size_etc
           2        2000    0.05       1  add_alloc_tracing_entry__FP11ObjectCacheUlPv
           2        2000    0.05       1  malloc
           2        2000    0.05       1  object_cache_free
           2        2000    0.05       1  size_to_index__FUl
           2        2000    0.05       1  geteuid
           1        1000    0.02       1  block_free__FPvUl
           1        1000    0.02       1  block_alloc__FUlUlUl
           1        1000    0.02       1  _kern_getuid
           1        1000    0.02       1  thread_block
           1        1000    0.02       1  getegid
           1        1000    0.02       1  _user_port_buffer_size_etc

[waddlesplash]

I just tried a quick profile of HaikuDepot, and I got a lot of results that were clearly in userland functions, e.g.:

profiling results for thread "LocalPkgDataLoadProcess" (4739):
  tick interval:  1000 us
  total ticks:    341 (341000 us)
  unknown ticks:  0 (0 us,   0.00%)
  dropped ticks:  0 (0 us,   0.00%)

        hits     unknown    image
  ------------------------------------------------------------------------------
           4           0    38481 /boot/system/apps/HaikuDepot
          97           0    38479 commpage
          40           0    38482 /boot/system/lib/libbe.so
          23           0    38483 /boot/system/lib/libpackage.so
         155           0    38487 /boot/system/lib/libroot.so
           8           0    38495 /boot/system/lib/libz.so.1.2.11

        hits       in us    in %   image  function
  ------------------------------------------------------------------------------
          86       86000   25.22   38479  commpage_syscall
          27       27000    7.92   38487  isValid__Q28BPrivate10superblock
          17       17000    4.99   38487  malloc__Q28BPrivate10threadHeapUl
          12       12000    3.52   38487  freeBlock__Q28BPrivate9hoardHeapRPQ28BPrivate5blockRPQ28BPrivate10superblockiPQ28BPrivate11processHeap
          11       11000    3.23   38487  atomic_add
          10       10000    2.93   38487  __mutex_lock
           9        9000    2.64   38487  strncpy
           8        8000    2.35   38487  computeFullness__Q28BPrivate10superblock
           7        7000    2.05   38495  inflate_fast

32-bit in VMware here.

[waddlesplash]

Brief investigation: profiling data in single-application mode just uses the user debugger, which merely invokes arch_debug_get_stack_trace to get stack-traces. Either this is broken in profiling mode (unlikely; and as we see userland images in the trace, the stack trace most probably also has kernel functions in it), the data is not making it to userland (improbable), the userland tool is misinterpreting it (most likely.)

[waddlesplash]

I spent some time today trying to narrow this down further. Unfortunately I did not get very far despite poking through quite a lot of the code. For me, userland functions always appear in per-application profiling, while kernel functions do or do not appear pretty randomly. There are 0 unknown methods (I checked) in the profiling results; so that points to, for whatever reason, no kernel methods showing up in the buffers, which would be very strange.

[waddlesplash]

Ha, I just noticed: in all instance, the ticks count is way too low, it's listed as only 300ms for the example I posted. Testing here with "jam" shows tick counts as low as 1! Somehow timer interrupts are just not firing, I guess?

[waddlesplash]

Fixed in hrev56274.