Hi,

I have a question about something strange I have noticed while collecting profiles using pfmon. When I run a single cold run of the 2to3 benchmark, the "time" command (or using --show-time) gives me:
$time /usr/local/bin/python -E -O benchmarks/unladen-swallow/lib/2to3/2to3 -f all benchmarks/unladen-swallow/lib/2to3 > /dev/null

real 0m19.523s
      user 0m19.485s         sys 0m0.044s

which shows dominating user time (actually system time is negligible). Now when running pfmon to do sampling every 10000 UNHALTED_CORE_CYCLES (or INSTRUCTIONS_RETIRED), the results show dominating kernel time 87% (see below). I am just wondering why there is such a difference. Am I missing something ?

pfmon --follow-all -k --long-smpl-period=100000 --resolve --smpl-per-function --smpl-outfile=pfmon_smpl /usr/local/bin/python -E -O
benchmarks/unladen-swallow/lib/2to3/2to3 -f all benchmarks/unladen-swallow/lib/2to3 > /dev/null

# results for [19867:19867<-[19864]] (/usr/local/bin/python)
# total samples          : 1529
# total buffer overflows : 1
#
#                   event00
#     counts   %self    %cum          code addr symbol
         360  23.54%  23.54% 0xffffffff80360f40 clear_page_c<kernel>
         252  16.48%  40.03% 0xffffffff80247160 __do_softirq<kernel>
         109   7.13%  47.16% 0xffffffff8028eaf0 get_page_from_freelist<kernel>
          65   4.25%  51.41% 0xffffffff802c9f60 __d_lookup<kernel>
          56   3.66%  55.07% 0xffffffff80477ef0 _spin_unlock_irqrestore<kernel>
          45   2.94%  58.01% 0xffffffff80479bc0 do_page_fault<kernel>
          41   2.68%  60.69% 0xffffffff80477dd0 _spin_lock<kernel>
          39   2.55%  63.24% 0xffffffff802c0ae0 __link_path_walk<kernel>
          36   2.35%  65.60% 0xffffffff80298b80 unmap_vmas<kernel>
          36   2.35%  67.95% 0xffffffff8028dc20 free_hot_cold_page<kernel>
          22   1.44%  69.39% 0x00007f65c75d0000 UNKNOWN</lib/libc-2.7.so>
          20   1.31%  70.70% 0xffffffff802999f0 handle_mm_fault<kernel>
          20   1.31%  72.01% 0xffffffff80292030 __pagevec_lru_add_active<kernel>
          17   1.11%  73.12% 0xffffffff8024afb0 run_timer_softirq<kernel>
          13   0.85%  73.97% 0xffffffff8035a540 _atomic_dec_and_lock<kernel>
          13   0.85%  74.82% 0xffffffff8028f390 __alloc_pages<kernel>
          13   0.85%  75.67% 0xffffffff8028c5f0 page_to_pfn<kernel>
          12   0.78%  76.46% 0xffffffff803619a0 __strncpy_from_user<kernel>
          12   0.78%  77.24% 0xffffffff802a1e90 anon_vma_prepare<kernel>
          12   0.78%  78.02% 0xffffffff80292860 lru_cache_add_active<kernel>
          11   0.72%  78.74% 0xffffffff80361240 copy_user_generic_string<kernel>
          11   0.72%  79.46% 0xffffffff802b0a60 kmem_cache_alloc<kernel>
          11   0.72%  80.18% 0xffffffff80276a60 cpuset_update_task_memory_state<kernel>
           9   0.59%  80.77% 0xffffffff88161a90 ext3_count_free_blocks[ext3]<kernel>
           9   0.59%  81.36% 0xffffffff802a7b20 alloc_page_vma<kernel>
           9   0.59%  81.95% 0xffffffff802a1080 page_remove_rmap<kernel>
           9   0.59%  82.54% 0xffffffff80291e70 release_pages<kernel>
           9   0.59%  83.13% 0xffffffff8028c5a0 pfn_to_page<kernel>
           9   0.59%  83.71% 0xffffffff8023c090 finish_task_switch<kernel>
           8   0.52%  84.24% 0xffffffff8029ce40 find_vma<kernel>
           7   0.46%  84.70% 0xffffffff802c1c00 do_path_lookup<kernel>
           7   0.46%  85.15% 0xffffffff802a6b20 get_vma_policy<kernel>
           7   0.46%  85.61% 0xffffffff8028c350 zone_watermark_ok<kernel>
           6   0.39%  86.00% 0xffffffff802be9f0 __follow_mount<kernel>
           6   0.39%  86.40% 0xffffffff802be780 permission<kernel>
           6   0.39%  86.79% 0xffffffff802be670 generic_permission<kernel>
           6   0.39%  87.18% 0xffffffff802965d0 __inc_zone_state<kernel>
           6   0.39%  87.57% 0x000000000048fee0 PyEval_EvalFrameEx</usr/local/bin/python>
thanks,
- nagy