Re: High system times on Scaleway Cloud server

[Alexander Nasonov <alnsn%yandex.ru@localhost>]

Alexander Nasonov wrote:
> # tprof monitor -e INST_RETIRED:k -o tprof.out sleep 30

Sorry for spamming the list, I'm still learning how to use tprof.

Non-agregated output isn't very useful, especially when measuring
a system with many short-lived processes.

I monitored the system for a bit longer and aggregated CPU,
lwp and processes (-CLP flags).

# tprof monitor -e CPU_CYCLES:k -o tprof.out sleep 300
# tprof analyze -CLP tprof.out 

File: tprof.out
Number of samples: 220

percentage   nsamples pid    lwp  cpu  k address          symbol
------------ -------- ------ ---- ---- - ---------------- ------
  27.727274%       61      0    0    0 1 ffffffc0000040a4 splx+0xbc
  12.727272%       28      0    0    0 1 ffffffc0003c7424 mutex_enter+0x124
  10.454545%       23      0    0    0 1 ffffffc0003e03f0 kobj_renamespace
   5.000000%       11      0    0    0 1 ffffffc0003e03fc kobj_renamespace+0xc
   4.090909%        9      0    0    0 1 ffffffc0003e0400 kobj_renamespace+0x10
   4.090909%        9      0    0    0 1 ffffffc0003e03f4 kobj_renamespace+0x4
   3.636364%        8      0    0    0 1 ffffffc0003c742c mutex_enter+0x12c
   1.363636%        3      0    0    0 1 ffffffc0003c73e4 mutex_enter+0xe4
   1.363636%        3      0    0    0 1 ffffffc0000653e8 trap_el0_sync+0x40
   1.363636%        3      0    0    0 1 ffffffc0003e2080 kpreempt_disabled
   0.909091%        2      0    0    0 1 ffffffc000004068 splx+0x80
   0.909091%        2      0    0    0 1 ffffffc000463f50 fstrans_start_nowait+0x140
   0.454545%        1      0    0    0 1 ffffffc00037cd30 amap_copy+0xd8
   0.454545%        1      0    0    0 1 ffffffc000391a74 uvm_page_compare_key+0xc
   0.454545%        1      0    0    0 1 ffffffc000394870 uvm_page_locked_p
   0.454545%        1      0    0    0 1 ffffffc00039563c uvm_aio_aiodone_pages+0xa4
   0.454545%        1      0    0    0 1 ffffffc000397294 uvmpdpol_pageactivate+0x24
   0.454545%        1      0    0    0 1 ffffffc000398eac uvm_physseg_find+0x44
   0.454545%        1      0    0    0 1 ffffffc000399100 uvm_physseg_get_pg+0x38
   0.454545%        1      0    0    0 1 ffffffc000399110 uvm_physseg_get_pg+0x48
   0.454545%        1      0    0    0 1 ffffffc0003adaa0 cpu_softintr_p
   0.454545%        1      0    0    0 1 ffffffc0003aeb18 fd_next_zero+0x98
   0.454545%        1      0    0    0 1 ffffffc0003afc88 fd_alloc
   0.454545%        1      0    0    0 1 ffffffc0003c0e2c _kernel_lock+0xa4
   0.454545%        1      0    0    0 1 ffffffc0003c70e8 mutex_oncpu
   0.454545%        1      0    0    0 1 ffffffc0003c70fc mutex_oncpu+0x14
   0.454545%        1      0    0    0 1 ffffffc0003c7114 mutex_oncpu+0x2c

# tprof monitor -e INST_RETIRED:k -o tprof.out sleep 300
# tprof analyze -CLP tprof.out
File: tprof.out
Number of samples: 25

percentage   nsamples pid    lwp  cpu  k address          symbol
------------ -------- ------ ---- ---- - ---------------- ------
  20.000000%        5      0    0    0 1 ffffffc0003c7424 mutex_enter+0x124
  20.000000%        5      0    0    0 1 ffffffc0003e03f0 kobj_renamespace
  12.000000%        3      0    0    0 1 ffffffc0003e03f4 kobj_renamespace+0x4
   8.000000%        2      0    0    0 1 ffffffc0003e0400 kobj_renamespace+0x10
   8.000000%        2      0    0    0 1 ffffffc0000040a4 splx+0xbc
   8.000000%        2      0    0    0 1 ffffffc0003c742c mutex_enter+0x12c
   4.000000%        1      0    0    0 1 ffffffc000464ef4 vstate_assert_get+0x2c
   4.000000%        1      0    0    0 1 ffffffc0001a5b74 xor16+0x4c
   4.000000%        1      0    0    0 1 ffffffc000450b54 cache_revlookup+0x15c
   4.000000%        1      0    0    0 1 ffffffc0004637bc fstrans_alloc_lwp_info+0x184
   4.000000%        1      0    0    0 1 ffffffc000463f50 fstrans_start_nowait+0x140
   4.000000%        1      0    0    0 0 00000002002ce19c <00000002002ce19c>


-- 
Alex