Re: Idle time in Oprofile

On 09/17/2014 06:06 AM, Sabra Gargouri wrote:
> Hi,
> In the context of my current activity witch intent to analyse Oprofile features, I would like to check if Oprofile is considering idle time in its profiling results. So for that purpose, I have run Oprofile without running any other application (the system is idle).  I used Oprofile in the timer mode.
> First, I have run Oprofile on SH4 platform, and as following results show, 93% used by "poll_idle". 
> 
> 15655    93.8437  vmlinux                  poll_idle
> 238       1.4267  vmlinux                  arch_local_irq_restore
> 28        0.1678  oprofiled                do_match
> 24        0.1439  oprofiled                pop_buffer_value
> 24        0.1439  vmlinux                  copy_page
> 18        0.1079  oprofiled                opd_process_samples
> 18        0.1079  oprofiled                sfile_find
> 16        0.0959  bash                     shell_getc
> 16        0.0959  libc-2.14.1.so           __gconv_transform_ascii_internal
> 16        0.0959  oprofiled                get_file
> 14        0.0839  libc-2.14.1.so           mbrtowc
> 14        0.0839  oprofiled                sfile_log_sample_count
> 13        0.0779  oprofiled                odb_update_node_with_offset
> 12        0.0719  libc-2.14.1.so           _int_malloc
> 9         0.0540  oprofiled                find_kernel_image
> 9         0.0540  vmlinux                  __copy_user
> 9         0.0540  vmlinux                  link_path_walk
> 9         0.0540  vmlinux                  nfs_permission
> 8         0.0480  ld-2.14.1.so             _dl_relocate_object
> 8         0.0480  vmlinux                  tcp_ack
> 
> I have also run Oprofile on ARM Cortex-a9 (SMP) whithout any application running (system is idle) and got 99.44% used by "fpa_get" function and there's nothing related to "idle".  
> 
> samples  %        app name                 symbol name
> 4148     99.4486  vmlinux                  fpa_get
> 2         0.0480  vmlinux                  print_cfs_rq
> 1         0.0240  bash                     hash_search
> 1         0.0240  bash                     parse_matched_pair
> 1         0.0240  gawk                     check_special
> 1         0.0240  ld-2.14.1.so             _dl_lookup_symbol_x
> 1         0.0240  libc-2.14.1.so           __default_morecore
> 1         0.0240  libc-2.14.1.so           __gconv_transform_ascii_internal
> 1         0.0240  libc-2.14.1.so           malloc_consolidate
> 1         0.0240  libc-2.14.1.so           strcpy
> 1         0.0240  vmlinux                  create_new_namespaces
> 1         0.0240  vmlinux                  dup_fd
> 1         0.0240  vmlinux                  fuse_copy_args
> 1         0.0240  vmlinux                  mnt_alloc_group_id
> 1         0.0240  vmlinux                  print_cpu
> 1         0.0240  vmlinux                  ptrace_request
> 1         0.0240  vmlinux                  seq_list_start_head
> 1         0.0240  vmlinux                  seq_write
> 1         0.0240  vmlinux                  usleep_range
> 1         0.0240  vmlinux                  vga_arbiter_notify_clients.part.11
> 1         0.0240  vmlinux                  vga_get
> 1         0.0240  vmlinux                  vm_insert_page
> 1         0.0240  vmlinux                  write_wb_reg
> 
> When searching in the official Oprofile documentation, I have found the following explanation
>  " Your kernel is likely to support halting the processor when a CPU is idle. As the typical hardware events like CPU_CLK_UNHALTED do not count when the CPU is halted, the kernel profile will not reflect the actual amount of time spent idle.You can change this behaviour by booting with the idle=poll option, which uses a different idle routine. This will appear as poll_idle() in your kernel profile".
> So I have rebooted my kernel with adding  idle=poll option, but I have not noticed any diffrence between the previous ones.
> 
> 4707     99.5137  vmlinux                  fpa_get
> 2         0.0423  vmlinux                  attribute_container_unregister
> 2         0.0423  vmlinux                  print_cfs_rq
> 1         0.0211  bash                     execute_command_internal
> 1         0.0211  bash                     shell_getc
> 1         0.0211  libc-2.14.1.so           __gconv_transform_ascii_internal
> 1         0.0211  libc-2.14.1.so           sigprocmask
> 1         0.0211  libdl-2.14.1.so          call_gmon_start
> 1         0.0211  vmlinux                  __getnstimeofday
> 1         0.0211  vmlinux                  bdi_min_pause.isra.19
> 1         0.0211  vmlinux                  cgroup_scan_tasks
> 1         0.0211  vmlinux                  dev_alert
> 1         0.0211  vmlinux                  ext2_block_to_path.isra.19
> 1         0.0211  vmlinux                  ext4_ext_remove_space
> 1         0.0211  vmlinux                  iterate_supers
> 1         0.0211  vmlinux                  lg_local_lock
> 1         0.0211  vmlinux                  pipe_to_file
> 1         0.0211  vmlinux                  ptrace_request
> 1         0.0211  vmlinux                  register_filesystem
> 1         0.0211  vmlinux                  seq_write
> 1         0.0211  vmlinux                  sys_prctl
> 1         0.0211  vmlinux                  ubi_start_leb_change
> 
> Why does "idle_poll" does not appear in the "ARM" case? does it relate to architectural reasons?
> Could we say that Oprofile is not intended to determine idle time ? or it's related to the configuration of the oprofile daemon?

Hi Sabra,

OProfile is generally using the performance monitoring hardware of the processor and the default events are usually unhalted clock cycles.  For reduced power consumption most kernels are configured to halt the processors when there is no work rather than having the processors doing idle polling.

OProfile may get sample for time spent idle when it is using timer interrupts or the kernel is configured to use the polling loop. If you want to looks that things based on wallclock, you might want to do something like the following to get samples when the processor is idle:


# opcontrol --deinit; modprobe oprofile timer=1
# opcontrol --start --vmlinux=/usr/lib/debug/lib/modules/`uname-r`/vmlinux --separate=library

On my arm machine I get the following for kernel samples when the processor is idle:

$ opreport -l -t2 /usr/lib/debug/lib/modules/3.16.2-200.fc20.armv7hl/vmlinux
Using /var/lib/oprofile/samples/ for samples directory.
CPU: CPU with timer interrupt, speed 1e+06 MHz (estimated)
Profiling through timer interrupt
samples  %        symbol name
35623    98.5449  cpuidle_enter_state


I don't know how long those runs are.  However, if you are using the defaults 100,000 clock cycles between samples, you would be getting about 10,000 samples a second. The 4000 or so samples for "fpa_get" could be pretty small amount. The fpa_get" appears to be in the arm specific ptrace to to get the FPA registers.  Is the code using ptrace?

-Will

------------------------------------------------------------------------------
Want excitement?
Manually upgrade your production database.
When you want reliability, choose Perforce
Perforce version control. Predictably reliable.
http://pubads.g.doubleclick.net/gampad/clk?id=157508191&iu=/4140/ostg.clktrk