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
------------------------------------------------------------------------------
Stay on top of everything new and different, both inside and
around Java (TM) technology - register by April 22, and save
$200 on the JavaOne (SM) conference, June 2-5, 2009, San Francisco.
300 plus technical and hands-on sessions. Register today.
Use priority code J9JMT32. http://p.sf.net/sfu/p
_______________________________________________
perfmon2-devel mailing list
perfmon2-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/perfmon2-devel
