| Summary: | [Performance] Use the profiling and tracing tools to see where build performance might be improved | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] OE-Core | Reporter: | Tom Zanussi <tom.zanussi> | ||||||
| Component: | core | Assignee: | Tom Zanussi <tom.zanussi> | ||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||
| Severity: | enhancement | ||||||||
| Priority: | Medium | CC: | bluelightning, dvhart, jessica.zhang, meta.mr.watcher, meta.watcher, n3npq, ross.burton | ||||||
| Version: | unspecified | ||||||||
| Target Milestone: | 1.5 | ||||||||
| Hardware: | x86 | ||||||||
| OS: | Multiple | ||||||||
| Whiteboard: | Investigating | ||||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||||
| Verified: | Documentation change: | Don't know | |||||||
| Attachments: |
|
||||||||
Just to add some more data, not really of much use at this point, here are a couple 'perf stat' runs of a complete core-image-sato build:
Performance counter stats for 'bitbake core-image-sato':
37987985.337044 task-clock # 6.032 CPUs utilized
130,409,320 context-switches # 0.003 M/sec
6,691,951 CPU-migrations # 0.176 K/sec
1,667,397,173 page-faults # 0.044 M/sec
124,518,869,052,519 cycles # 3.278 GHz
86,494,970,822,771 stalled-cycles-frontend # 69.46% frontend cycles idle
<not supported> stalled-cycles-backend
96,637,624,444,770 instructions # 0.78 insns per cycle
# 0.90 stalled cycles per insn
20,625,976,149,289 branches # 542.961 M/sec
768,953,422,109 branch-misses # 3.73% of all branches
6297.324834180 seconds time elapsed
real 104m57.376s
user 512m59.520s
sys 75m32.972s
[trz@empanada build]$ time perf stat -e sched:* bitbake core-image-sato
Performance counter stats for 'bitbake core-image-sato':
0 sched:sched_pi_setprio
41,296,743,206,821 sched:sched_stat_runtime
43,107,064,258,390 sched:sched_stat_blocked
18,142,740,882,781 sched:sched_stat_iowait
1,221,301,402,939,330 sched:sched_stat_sleep
123,872,699,896,920 sched:sched_stat_wait
2,068,855 sched:sched_process_exec
3,133,040 sched:sched_process_fork
6,542,382 sched:sched_process_wait
0 sched:sched_wait_task
3,133,040 sched:sched_process_exit
2,302,142 sched:sched_process_free
13,155,138 sched:sched_migrate_task
134,844,335 sched:sched_switch
6,266,080 sched:sched_wakeup_new
173,477,616 sched:sched_wakeup
0 sched:sched_kthread_stop_ret
0 sched:sched_kthread_stop
7464.933421279 seconds time elapsed
real 124m25.012s
user 554m15.857s
sys 94m54.101s
Created attachment 944 [details]
linux-yocto pybootchart
So, digging a little further... A build of linux-yocto using the default rpm packaging shows the timings below with rpm packaging: $ bitbake -c clean linux-yocto $ bitbake -c cleansstate linux-yocto $ time bitbake linux-yocto PACKAGE_CLASSES ?= "package_rpm" real 16m27.826s user 23m43.115s sys 5m27.270s Here's the same thing with ipk packaging: PACKAGE_CLASSES ?= "package_ipk" real 14m51.376s user 22m21.045s sys 6m47.513s So, a bit of difference but not that much - originally I had been inclined to blame the extremely long build time on rpm, but that doesn't seem to be the case. So from here on, we'll just stick with the default rpm. See the attached pychart-linux-yocto-rpm.png to see what the linux-yocto build looks like graphically. It was generated using: ../scripts/pybootchartgui/pybootchartgui.py ../build/tmp/buildstats/linux-yocto-sugarbay/201211191046/ Breaking it down into rough numbers, each major phase of the build has timings that look like this: do_compile (2 min) do_compile_kernelmodules (30 sec) do_install (3 min) do_package (7 min) do_package_write (4 min) What's surprising is how much of the total build time is devoted to packaging (about 11 out of 17 minutes) and install (3 out of 17 minutes). I don't know how typical that is, but something seems wrong if it takes that much longer to package the output than it does to create it. To see where time is being spent in both do_package and do_package_write, I ran a profile using: # perf record -a -g during a fresh the bitbake linux-yocto run during the entire do_package and do_package_write phases. The overall run looked like this: + 9.22% gzip gzip [.] longest_match ◆ + 5.68% rpmdeps-oecore. libc-2.15.so [.] re_search_internal ▒ + 3.66% swapper [kernel.kallsyms] [k] intel_idle ▒ + 2.95% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_strncmp ▒ + 1.88% gzip gzip [.] deflate ▒ + 1.79% python libpython2.7.so.1.0 [.] PyObject_RichCompare ▒ + 1.52% rpmdeps-oecore. libc-2.15.so [.] re_string_reconstruct ▒ + 1.47% pseudo pseudo [.] sqlite3VdbeExec ▒ + 1.18% rpmdeps-oecore. libc-2.15.so [.] re_string_context_at ▒ + 1.08% python libpython2.7.so.1.0 [.] PyEval_EvalFrameEx ▒ + 1.08% python [kernel.kallsyms] [k] __d_lookup_rcu ▒ + 1.01% rpmdeps-oecore. libmagic.so.1.0.0 [.] magiccheck ▒ + 1.00% python libpython2.7.so.1.0 [.] string_richcompare ▒ + 0.88% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_softmagic ▒ + 0.85% python libpython2.7.so.1.0 [.] PyObject_RichCompareBool ▒ + 0.84% python [kernel.kallsyms] [k] link_path_walk ▒ + 0.82% pseudo pseudo [.] pcache1Fetch ▒ + 0.79% gzip gzip [.] updcrc ▒ + 0.71% python [kernel.kallsyms] [k] copy_pte_range ▒ + 0.68% pseudo pseudo [.] sqlite3BtreeMovetoUnpacked ▒ + 0.68% python [kernel.kallsyms] [k] avc_has_perm_noaudit ▒ + 0.61% pseudo libc-2.15.so [.] __memcmp_sse4_1 ▒ + 0.60% pseudo libpthread-2.15.so [.] __pthread_mutex_unlock_user▒ + 0.59% pseudo libc-2.15.so [.] __memcpy_ssse3_back ▒ + 0.58% pseudo libc-2.15.so [.] _int_malloc ▒ + 0.58% gzip gzip [.] fill_window ▒ + 0.51% gzip gzip [.] ct_tally ▒ + 0.51% rpmdeps-oecore. libc-2.15.so [.] _int_malloc ▒ + 0.50% gzip gzip [.] compress_block ▒ + 0.48% pseudo libpthread-2.15.so [.] pthread_mutex_lock ▒ + 0.46% gzip gzip [.] send_bits ▒ + 0.45% swapper [kernel.kallsyms] [k] __schedule ▒ + 0.42% pseudo libc-2.15.so [.] _int_free ▒ + 0.40% python [kernel.kallsyms] [k] system_call ▒ + 0.38% python [kernel.kallsyms] [k] selinux_inode_permission ▒ + 0.37% pseudo pseudo [.] accessPayload ▒ + 0.36% pseudo pseudo [.] sqlite3VdbeRecordCompare ▒ + 0.35% swapper [kernel.kallsyms] [k] native_write_msr_safe ▒ + 0.34% python [kernel.kallsyms] [k] lookup_fast ▒ + 0.33% pseudo pseudo [.] sqlite3VdbeHalt ▒ + 0.32% pseudo [kernel.kallsyms] [k] _raw_spin_lock_irqsave ▒ + 0.29% pseudo [kernel.kallsyms] [k] copy_user_enhanced_fast_str▒ + 0.28% python [kernel.kallsyms] [k] __audit_syscall_exit ▒ + 0.28% swapper [kernel.kallsyms] [k] menu_select ▒ + 0.27% python [kernel.kallsyms] [k] copy_user_enhanced_fast_str▒ The top few consumers of cycles in the above summary were gzip, rpmdeps-oecore, python, and pseudo. For each of those, the output from zooming into the thread is shown. Here's gzip: + 64.65% gzip gzip [.] longest_match ▒ + 13.16% gzip gzip [.] deflate ▒ + 5.55% gzip gzip [.] updcrc ◆ + 4.04% gzip gzip [.] fill_window ▒ + 3.61% gzip gzip [.] ct_tally ▒ + 3.48% gzip gzip [.] compress_block ▒ + 3.20% gzip gzip [.] send_bits ▒ + 0.62% gzip gzip [.] pqdownheap ▒ + 0.18% gzip [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 0.13% gzip gzip [.] build_tree ▒ + 0.11% gzip gzip [.] copy_block ▒ + 0.09% gzip libc-2.15.so [.] __memcpy_ssse3_back ▒ + 0.05% gzip gzip [.] bi_reverse ▒ + 0.04% gzip gzip [.] gen_codes ▒ + 0.04% gzip gzip [.] scan_tree ▒ + 0.03% gzip [kernel.kallsyms] [k] free_pcppages_bulk ▒ + 0.03% gzip [kernel.kallsyms] [k] native_write_msr_safe ▒ + 0.02% gzip [kernel.kallsyms] [k] _raw_spin_lock ▒ + 0.02% gzip gzip [.] send_tree ▒ + 0.02% gzip [kernel.kallsyms] [k] get_page_from_freelist ▒ + 0.02% gzip [kernel.kallsyms] [k] __list_del_entry ▒ + 0.02% gzip [kernel.kallsyms] [k] pipe_read ▒ + 0.02% gzip [kernel.kallsyms] [k] ext4_mark_iloc_dirty ▒ + 0.02% gzip [kernel.kallsyms] [k] apic_timer_interrupt ▒ + 0.01% gzip [kernel.kallsyms] [k] __rmqueue ▒ + 0.01% gzip [kernel.kallsyms] [k] __mark_inode_dirty ▒ + 0.01% gzip [kernel.kallsyms] [k] update_curr ▒ + 0.01% gzip [kernel.kallsyms] [k] anon_pipe_buf_release ▒ + 0.01% gzip [kernel.kallsyms] [k] kmem_cache_alloc ▒ + 0.01% gzip [kernel.kallsyms] [k] _raw_spin_lock_irqsave ▒ + 0.01% gzip [kernel.kallsyms] [k] run_timer_softirq ▒ + 0.01% gzip [kernel.kallsyms] [k] irqtime_account_irq ▒ + 0.01% gzip [kernel.kallsyms] [k] bad_range ▒ + 0.01% gzip [kernel.kallsyms] [k] avc_has_perm_flags ▒ + 0.01% gzip [kernel.kallsyms] [k] trigger_load_balance ▒ + 0.01% gzip [kernel.kallsyms] [k] select_task_rq_fair ▒ + 0.01% gzip [kernel.kallsyms] [k] ext4_bio_write_page ▒ + 0.01% gzip [kernel.kallsyms] [k] jbd2_journal_stop ▒ + 0.01% gzip [kernel.kallsyms] [k] radix_tree_lookup_element ▒ + 0.01% gzip [kernel.kallsyms] [k] update_cfs_rq_blocked_load ▒ + 0.01% gzip [kernel.kallsyms] [k] selinux_file_permission ▒ + 0.01% gzip [kernel.kallsyms] [k] rcu_check_callbacks ▒ + 0.01% gzip [kernel.kallsyms] [k] update_cfs_shares ▒ + 0.01% gzip [kernel.kallsyms] [k] mpage_da_submit_io ▒ + 0.01% gzip [kernel.kallsyms] [k] ext4_journal_start_sb ▒ Here's rpmdeps-oecore: + 30.49% rpmdeps-oecore. libc-2.15.so [.] re_search_internal ◆ + 15.85% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_strncmp ▒ + 8.17% rpmdeps-oecore. libc-2.15.so [.] re_string_reconstruct ▒ + 6.32% rpmdeps-oecore. libc-2.15.so [.] re_string_context_at ▒ + 5.42% rpmdeps-oecore. libmagic.so.1.0.0 [.] magiccheck ▒ + 4.73% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_softmagic ▒ + 2.72% rpmdeps-oecore. libc-2.15.so [.] _int_malloc ▒ + 1.34% rpmdeps-oecore. libc-2.15.so [.] _int_free ▒ + 1.27% rpmdeps-oecore. libc-2.15.so [.] re_compile_internal ▒ + 1.17% rpmdeps-oecore. libc-2.15.so [.] __strcmp_sse42 ▒ + 1.03% rpmdeps-oecore. libmagic.so.1.0.0 [.] mget ▒ + 1.02% rpmdeps-oecore. libc-2.15.so [.] malloc_consolidate ▒ + 1.00% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_ascmagic_with_encoding ▒ + 0.76% rpmdeps-oecore. libc-2.15.so [.] parse_expression ▒ + 0.71% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_encoding ▒ + 0.69% rpmdeps-oecore. libc-2.15.so [.] msort_with_tmp.part.0 ▒ + 0.69% rpmdeps-oecore. libc-2.15.so [.] build_trtable ▒ + 0.68% rpmdeps-oecore. [kernel.kallsyms] [k] __d_lookup_rcu ▒ + 0.66% rpmdeps-oecore. libmagic.so.1.0.0 [.] mcopy ▒ + 0.61% rpmdeps-oecore. libc-2.15.so [.] malloc ▒ + 0.58% rpmdeps-oecore. libc-2.15.so [.] __ctype_get_mb_cur_max ▒ + 0.53% rpmdeps-oecore. [kernel.kallsyms] [k] link_path_walk ▒ + 0.50% rpmdeps-oecore. ld-2.15.so [.] do_lookup_x ▒ + 0.49% rpmdeps-oecore. libc-2.15.so [.] free_dfa_content ▒ + 0.49% rpmdeps-oecore. libc-2.15.so [.] __ctype_b_loc ▒ + 0.46% rpmdeps-oecore. libc-2.15.so [.] __memset_sse2 ▒ + 0.44% rpmdeps-oecore. libc-2.15.so [.] free ▒ + 0.42% rpmdeps-oecore. libmagic.so.1.0.0 [.] __ctype_b_loc@plt ▒ + 0.41% rpmdeps-oecore. [kernel.kallsyms] [k] page_fault ▒ + 0.40% rpmdeps-oecore. [kernel.kallsyms] [k] avc_has_perm_noaudit ▒ + 0.40% rpmdeps-oecore. libc-2.15.so [.] calc_eclosure_iter ▒ + 0.40% rpmdeps-oecore. [kernel.kallsyms] [k] unmap_single_vma ▒ + 0.36% rpmdeps-oecore. libc-2.15.so [.] __memcpy_sse2 ▒ + 0.35% rpmdeps-oecore. libc-2.15.so [.] re_compile_fastmap_iter.isra.29 ▒ + 0.33% rpmdeps-oecore. libc-2.15.so [.] create_cd_newstate ▒ + 0.32% rpmdeps-oecore. librpmio-5.4.so [.] compareMacroName ▒ + 0.28% rpmdeps-oecore. libmagic.so.1.0.0 [.] file_signextend ▒ + 0.28% rpmdeps-oecore. libc-2.15.so [.] __mbrtowc ▒ + 0.27% rpmdeps-oecore. libc-2.15.so [.] link_nfa_nodes ▒ + 0.26% rpmdeps-oecore. libc-2.15.so [.] peek_token ▒ + 0.25% rpmdeps-oecore. [kernel.kallsyms] [k] system_call ▒ + 0.23% rpmdeps-oecore. libc-2.15.so [.] __gconv_transform_ascii_internal ▒ + 0.23% rpmdeps-oecore. libc-2.15.so [.] __libc_calloc ▒ + 0.22% rpmdeps-oecore. libc-2.15.so [.] re_dfa_add_node ▒ + 0.21% rpmdeps-oecore. [kernel.kallsyms] [k] lookup_fast ▒ Here's python: + 15.09% python libpython2.7.so.1.0 [.] PyObject_RichCompare ◆ + 9.07% python libpython2.7.so.1.0 [.] PyEval_EvalFrameEx ▒ + 7.19% python libpython2.7.so.1.0 [.] PyObject_RichCompareBool ▒ + 5.99% python [kernel.kallsyms] [k] copy_pte_range ▒ + 3.35% python [kernel.kallsyms] [k] system_call ▒ + 2.36% python [kernel.kallsyms] [k] __audit_syscall_exit ▒ + 2.27% python [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 2.13% python libpython2.7.so.1.0 [.] list_contains ▒ + 1.68% python [kernel.kallsyms] [k] _raw_spin_lock ▒ + 1.50% python libpython2.7.so.1.0 [.] lookdict_string ▒ + 1.49% python [kernel.kallsyms] [k] __audit_syscall_entry ▒ + 1.47% python [kernel.kallsyms] [k] avc_has_perm_flags ▒ + 1.28% python [kernel.kallsyms] [k] _raw_spin_lock_irq ▒ + 1.18% python libc-2.15.so [.] _int_malloc ▒ + 1.05% python libpython2.7.so.1.0 [.] _PyObject_GenericGetAttrWithDict ▒ + 1.00% python libpython2.7.so.1.0 [.] PyObject_Malloc ▒ + 0.98% python libpython2.7.so.1.0 [.] _PyType_Lookup ▒ + 0.95% python [kernel.kallsyms] [k] _raw_spin_lock_irqsave ▒ + 0.92% python libc-2.15.so [.] __memcmp_sse4_1 ▒ + 0.90% python libc-2.15.so [.] _int_free ▒ + 0.82% python libc-2.15.so [.] __memcpy_ssse3_back ▒ + 0.75% python [kernel.kallsyms] [k] __schedule ▒ + 0.71% python [kernel.kallsyms] [k] page_fault ▒ + 0.68% python [kernel.kallsyms] [k] __switch_to ▒ + 0.66% python libpython2.7.so.1.0 [.] PyDict_GetItem ▒ + 0.62% python libc-2.15.so [.] __strchr_sse42 ▒ + 0.59% python [kernel.kallsyms] [k] inode_has_perm.isra.30.constprop.60 ▒ + 0.59% python libpython2.7.so.1.0 [.] vgetargs1 ▒ + 0.58% python libpython2.7.so.1.0 [.] convertitem ▒ + 0.58% python [kernel.kallsyms] [k] dput ▒ + 0.56% python libpython2.7.so.1.0 [.] PyObject_GetAttr ▒ + 0.55% python [kernel.kallsyms] [k] copy_page_rep ▒ + 0.55% python [kernel.kallsyms] [k] kfree ▒ + 0.54% python libc-2.15.so [.] __strlen_sse2_pminub ▒ + 0.50% python libpython2.7.so.1.0 [.] PyObject_Free ▒ + 0.49% python libc-2.15.so [.] malloc ▒ + 0.49% python [kernel.kallsyms] [k] sysret_check ▒ + 0.49% python libpython2.7.so.1.0 [.] PyFrame_New ▒ + 0.48% python libpthread-2.15.so [.] pthread_self ▒ + 0.45% python libpython2.7.so.1.0 [.] frame_dealloc ▒ + 0.44% python [kernel.kallsyms] [k] path_put ▒ + 0.42% python libc-2.15.so [.] free ▒ + 0.41% python libpython2.7.so.1.0 [.] PyInt_FromLong ▒ + 0.40% python [kernel.kallsyms] [k] unroll_tree_refs ▒ + 0.39% python libpthread-2.15.so [.] __errno_location ▒ And here's pseudo: + 6.63% pseudo pseudo [.] sqlite3VdbeExec ◆ + 3.69% pseudo pseudo [.] pcache1Fetch ▒ + 3.08% pseudo pseudo [.] sqlite3BtreeMovetoUnpacked ▒ + 2.72% pseudo libc-2.15.so [.] __memcmp_sse4_1 ▒ + 2.70% pseudo libpthread-2.15.so [.] __pthread_mutex_unlock_usercnt ▒ + 2.65% pseudo libc-2.15.so [.] __memcpy_ssse3_back ▒ + 2.61% pseudo libc-2.15.so [.] _int_malloc ▒ + 2.18% pseudo libpthread-2.15.so [.] pthread_mutex_lock ▒ + 1.90% pseudo libc-2.15.so [.] _int_free ▒ + 1.65% pseudo pseudo [.] accessPayload ▒ + 1.63% pseudo pseudo [.] sqlite3VdbeRecordCompare ▒ + 1.47% pseudo pseudo [.] sqlite3VdbeHalt ▒ + 1.46% pseudo [kernel.kallsyms] [k] _raw_spin_lock_irqsave ▒ + 1.30% pseudo [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 1.20% pseudo pseudo [.] pseudo_server_start ▒ + 1.05% pseudo pseudo [.] sqlite3PcacheFetch ▒ + 1.03% pseudo pseudo [.] pcache1PinPage ▒ + 1.02% pseudo pseudo [.] sqlite3VdbeMemSetStr ▒ + 0.87% pseudo [kernel.kallsyms] [k] _raw_spin_lock ▒ + 0.85% pseudo pseudo [.] sqlite3MemCompare ▒ + 0.84% pseudo pseudo [.] pcache1Unpin ▒ + 0.83% pseudo pseudo [.] pseudo_op ▒ + 0.80% pseudo [kernel.kallsyms] [k] effective_load.isra.32 ▒ + 0.78% pseudo [kernel.kallsyms] [k] enqueue_entity ▒ + 0.75% pseudo [kernel.kallsyms] [k] unix_poll ▒ + 0.74% pseudo pseudo [.] sqlite3VdbeSerialGet ▒ + 0.73% pseudo pseudo [.] btreeParseCellPtr ▒ + 0.71% pseudo [kernel.kallsyms] [k] system_call ▒ + 0.67% pseudo pseudo [.] sqlite3PagerAcquire ▒ + 0.66% pseudo [kernel.kallsyms] [k] try_to_wake_up ▒ + 0.63% pseudo [kernel.kallsyms] [k] do_select ▒ + 0.62% pseudo [kernel.kallsyms] [k] __audit_syscall_exit ▒ + 0.62% pseudo pseudo [.] sqlite3BtreeBeginTrans ▒ + 0.60% pseudo [kernel.kallsyms] [k] unix_stream_recvmsg ▒ + 0.59% pseudo libc-2.15.so [.] malloc ▒ + 0.58% pseudo [kernel.kallsyms] [k] resched_task ▒ + 0.58% pseudo [kernel.kallsyms] [k] avc_has_perm_flags ▒ + 0.54% pseudo [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore ▒ + 0.54% pseudo [kernel.kallsyms] [k] update_curr ▒ + 0.53% pseudo [kernel.kallsyms] [k] select_task_rq_fair ▒ + 0.52% pseudo pseudo [.] sqlite3PcacheRelease ▒ + 0.50% pseudo [kernel.kallsyms] [k] fget_light ▒ + 0.49% pseudo pseudo [.] binCollFunc ▒ + 0.48% pseudo pseudo [.] mallocWithAlarm ▒ + 0.47% pseudo [kernel.kallsyms] [k] __slab_free ▒ Similarly, for package-write, here's the overall summary: + 31.22% rpmbuild.real libz.so.1.2.7 [.] longest_match + 8.86% rpmbuild.real libc-2.15.so [.] re_search_internal + 4.76% rpmbuild.real libmagic.so.1.0.0 [.] file_strncmp + 2.51% rpmbuild.real libc-2.15.so [.] __strcmp_sse42 + 2.41% rpmbuild.real libc-2.15.so [.] re_string_reconstruct + 2.14% swapper [kernel.kallsyms] [k] intel_idle + 2.09% rpmbuild.real libz.so.1.2.7 [.] deflate_slow + 1.80% rpmbuild.real libc-2.15.so [.] re_string_context_at + 1.50% rpmbuild.real libmagic.so.1.0.0 [.] magiccheck + 1.36% rpmbuild.real libmagic.so.1.0.0 [.] file_softmagic + 1.29% rpmbuild.real librpm-5.4.so [.] fsmStage + 1.08% gzip gzip [.] deflate + 0.91% python libpython2.7.so.1.0 [.] PyEval_EvalFrameEx + 0.79% rpmbuild.real librpmbuild-5.4.so [.] genCpioListAndHeader + 0.70% rpmbuild.real libc-2.15.so [.] _int_malloc + 0.66% gzip gzip [.] longest_match + 0.65% rpmbuild.real libz.so.1.2.7 [.] compress_block + 0.63% rpmbuild.real librpmio-5.4.so [.] gzdWrite + 0.53% rpmbuild.real libz.so.1.2.7 [.] pqdownheap + 0.49% rpmbuild.real librpmbuild-5.4.so [.] processPackageFiles + 0.49% rpmbuild.real [kernel.kallsyms] [k] __d_lookup_rcu + 0.43% rpmbuild.real libz.so.1.2.7 [.] fill_window + 0.41% rpmbuild.real libc-2.15.so [.] _int_free + 0.36% rpmbuild.real libc-2.15.so [.] re_compile_internal + 0.36% pseudo pseudo [.] sqlite3VdbeExec + 0.35% gzip gzip [.] ct_tally + 0.34% rpmbuild.real [kernel.kallsyms] [k] link_path_walk + 0.33% rpmbuild.real [kernel.kallsyms] [k] avc_has_perm_noaudit + 0.32% rpmbuild.real libbeecrypt.so.7.0.0 [.] md5Process + 0.30% rpmbuild.real libmagic.so.1.0.0 [.] mget + 0.29% rpmbuild.real libmagic.so.1.0.0 [.] file_ascmagic_with_encoding + 0.26% rpmbuild.real librpmio-5.4.so [.] argvCount + 0.24% python libpython2.7.so.1.0 [.] lookdict_string + 0.23% rpmbuild.real libz.so.1.2.7 [.] crc32 + 0.21% rpmbuild.real libc-2.15.so [.] parse_expression + 0.21% rpmbuild.real libz.so.1.2.7 [.] build_tree + 0.20% gzip gzip [.] updcrc + 0.20% rpmbuild.real libmagic.so.1.0.0 [.] file_encoding + 0.20% rpmbuild.real libc-2.15.so [.] malloc_consolidate + 0.20% rpmbuild.real libmagic.so.1.0.0 [.] mcopy + 0.19% rpmbuild.real libc-2.15.so [.] build_trtable + 0.19% rpmbuild.real [kernel.kallsyms] [k] system_call + 0.19% rpmbuild.real libc-2.15.so [.] __stpcpy_sse2_unaligned + 0.18% pseudo pseudo [.] pcache1Fetch + 0.18% pseudo pseudo [.] sqlite3BtreeMovetoUnpacked And zooming into the top consumers, here's rpmbuild.real first: + 41.54% rpmbuild.real libz.so.1.2.7 [.] longest_match ◆ + 11.79% rpmbuild.real libc-2.15.so [.] re_search_internal ▒ + 6.34% rpmbuild.real libmagic.so.1.0.0 [.] file_strncmp ▒ + 3.34% rpmbuild.real libc-2.15.so [.] __strcmp_sse42 ▒ + 3.21% rpmbuild.real libc-2.15.so [.] re_string_reconstruct ▒ + 2.78% rpmbuild.real libz.so.1.2.7 [.] deflate_slow ▒ + 2.40% rpmbuild.real libc-2.15.so [.] re_string_context_at ▒ + 1.99% rpmbuild.real libmagic.so.1.0.0 [.] magiccheck ▒ + 1.81% rpmbuild.real libmagic.so.1.0.0 [.] file_softmagic ▒ + 1.71% rpmbuild.real librpm-5.4.so [.] fsmStage ▒ + 1.05% rpmbuild.real librpmbuild-5.4.so [.] genCpioListAndHeader ▒ + 0.94% rpmbuild.real libc-2.15.so [.] _int_malloc ▒ + 0.86% rpmbuild.real libz.so.1.2.7 [.] compress_block ▒ + 0.83% rpmbuild.real librpmio-5.4.so [.] gzdWrite ▒ + 0.71% rpmbuild.real libz.so.1.2.7 [.] pqdownheap ▒ + 0.66% rpmbuild.real librpmbuild-5.4.so [.] processPackageFiles ▒ + 0.66% rpmbuild.real [kernel.kallsyms] [k] __d_lookup_rcu ▒ + 0.58% rpmbuild.real libz.so.1.2.7 [.] fill_window ▒ + 0.54% rpmbuild.real libc-2.15.so [.] _int_free ▒ + 0.49% rpmbuild.real libc-2.15.so [.] re_compile_internal ▒ + 0.45% rpmbuild.real [kernel.kallsyms] [k] link_path_walk ▒ + 0.43% rpmbuild.real [kernel.kallsyms] [k] avc_has_perm_noaudit ▒ + 0.43% rpmbuild.real libbeecrypt.so.7.0.0 [.] md5Process ▒ + 0.40% rpmbuild.real libmagic.so.1.0.0 [.] mget ▒ + 0.38% rpmbuild.real libmagic.so.1.0.0 [.] file_ascmagic_with_encoding ▒ + 0.34% rpmbuild.real librpmio-5.4.so [.] argvCount ▒ + 0.31% rpmbuild.real libz.so.1.2.7 [.] crc32 ▒ + 0.28% rpmbuild.real libc-2.15.so [.] parse_expression ▒ + 0.27% rpmbuild.real libz.so.1.2.7 [.] build_tree ▒ + 0.27% rpmbuild.real libmagic.so.1.0.0 [.] file_encoding ▒ + 0.27% rpmbuild.real libc-2.15.so [.] malloc_consolidate ▒ + 0.26% rpmbuild.real libmagic.so.1.0.0 [.] mcopy ▒ + 0.25% rpmbuild.real libc-2.15.so [.] build_trtable ▒ + 0.25% rpmbuild.real [kernel.kallsyms] [k] system_call ▒ + 0.25% rpmbuild.real libc-2.15.so [.] __stpcpy_sse2_unaligned ▒ + 0.24% rpmbuild.real libc-2.15.so [.] malloc ▒ + 0.22% rpmbuild.real [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 0.22% rpmbuild.real [kernel.kallsyms] [k] selinux_inode_permission ▒ + 0.21% rpmbuild.real libc-2.15.so [.] __memset_sse2 ▒ + 0.21% rpmbuild.real [kernel.kallsyms] [k] lookup_fast ▒ + 0.19% rpmbuild.real libc-2.15.so [.] free_dfa_content ▒ + 0.18% rpmbuild.real libc-2.15.so [.] free ▒ + 0.17% rpmbuild.real libc-2.15.so [.] __ctype_b_loc ▒ + 0.16% rpmbuild.real libmagic.so.1.0.0 [.] __ctype_b_loc@plt ▒ + 0.15% rpmbuild.real libc-2.15.so [.] calc_eclosure_iter ▒ Here's gzip: + 36.91% gzip gzip [.] deflate ◆ + 22.45% gzip gzip [.] longest_match ▒ + 11.98% gzip gzip [.] ct_tally ▒ + 7.01% gzip gzip [.] updcrc ▒ + 5.44% gzip gzip [.] fill_window ▒ + 5.30% gzip gzip [.] send_bits ▒ + 2.96% gzip gzip [.] compress_block ▒ + 2.45% gzip gzip [.] pqdownheap ▒ + 1.92% gzip gzip [.] copy_block ▒ + 0.44% gzip gzip [.] build_tree ▒ + 0.38% gzip [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 0.17% gzip gzip [.] bi_reverse ▒ + 0.17% gzip libc-2.15.so [.] __memcpy_ssse3_back ▒ + 0.07% gzip gzip [.] gen_codes ▒ + 0.06% gzip gzip [.] scan_tree ▒ + 0.05% gzip [kernel.kallsyms] [k] ext4_da_get_block_prep ▒ + 0.05% gzip [kernel.kallsyms] [k] _raw_spin_lock ▒ + 0.05% gzip [kernel.kallsyms] [k] __ext4_get_inode_loc ▒ + 0.05% gzip [kernel.kallsyms] [k] free_pcppages_bulk ▒ + 0.05% gzip [kernel.kallsyms] [k] __mark_inode_dirty ▒ + 0.05% gzip [kernel.kallsyms] [k] start_this_handle.isra.8 ▒ + 0.05% gzip [kernel.kallsyms] [k] get_page_from_freelist ▒ + 0.04% gzip [kernel.kallsyms] [k] ext4_bio_write_page ▒ + 0.04% gzip [kernel.kallsyms] [k] do_get_write_access ▒ + 0.04% gzip [kernel.kallsyms] [k] ext4_mark_iloc_dirty ▒ + 0.04% gzip [kernel.kallsyms] [k] __rmqueue ▒ + 0.04% gzip [kernel.kallsyms] [k] mpage_da_submit_io ▒ + 0.04% gzip [kernel.kallsyms] [k] radix_tree_lookup_element ▒ + 0.03% gzip [kernel.kallsyms] [k] apic_timer_interrupt ▒ + 0.03% gzip [kernel.kallsyms] [k] mark_page_accessed ▒ + 0.03% gzip [kernel.kallsyms] [k] __alloc_pages_nodemask ▒ + 0.03% gzip [kernel.kallsyms] [k] kmem_cache_alloc ▒ + 0.03% gzip [kernel.kallsyms] [k] select_task_rq_fair ▒ + 0.03% gzip [kernel.kallsyms] [k] enqueue_entity ▒ + 0.03% gzip gzip [.] send_tree ▒ + 0.03% gzip [kernel.kallsyms] [k] pipe_read ▒ + 0.03% gzip [kernel.kallsyms] [k] bad_range ▒ + 0.03% gzip [kernel.kallsyms] [k] __ext4_handle_dirty_metadata ▒ + 0.03% gzip [kernel.kallsyms] [k] put_page ▒ + 0.03% gzip [kernel.kallsyms] [k] release_pages ▒ + 0.02% gzip [kernel.kallsyms] [k] free_hot_cold_page ▒ + 0.02% gzip [kernel.kallsyms] [k] __inc_zone_state ▒ + 0.02% gzip [kernel.kallsyms] [k] __audit_syscall_entry ▒ + 0.02% gzip [kernel.kallsyms] [k] __x2apic_send_IPI_mask ▒ + 0.02% gzip [kernel.kallsyms] [k] __generic_file_aio_write ▒ And python: + 21.19% python libpython2.7.so.1.0 [.] PyEval_EvalFrameEx ◆ + 5.53% python libpython2.7.so.1.0 [.] lookdict_string ▒ + 3.70% python libpython2.7.so.1.0 [.] PyObject_Malloc ▒ + 3.17% python libc-2.15.so [.] _int_malloc ▒ + 2.62% python libpython2.7.so.1.0 [.] _PyType_Lookup ▒ + 2.60% python [kernel.kallsyms] [k] page_fault ▒ + 2.14% python libc-2.15.so [.] __memcpy_ssse3_back ▒ + 1.78% python libpython2.7.so.1.0 [.] PyDict_GetItem ▒ + 1.70% python libpython2.7.so.1.0 [.] _PyObject_GenericGetAttrWithDict ▒ + 1.66% python libpython2.7.so.1.0 [.] state_init.isra.12 ▒ + 1.65% python libpython2.7.so.1.0 [.] string_hash ▒ + 1.64% python libpython2.7.so.1.0 [.] sre_match ▒ + 1.58% python libc-2.15.so [.] _int_free ▒ + 1.41% python libpython2.7.so.1.0 [.] PyTuple_New ▒ + 1.27% python [kernel.kallsyms] [k] system_call ▒ + 1.20% python libpython2.7.so.1.0 [.] tupledealloc ▒ + 1.10% python libpython2.7.so.1.0 [.] PyObject_GetAttr ▒ + 1.01% python libc-2.15.so [.] __strlen_sse2_pminub ▒ + 1.00% python [kernel.kallsyms] [k] copy_user_enhanced_fast_string ▒ + 0.98% python libpython2.7.so.1.0 [.] PyObject_Free ▒ + 0.92% python [kernel.kallsyms] [k] _raw_spin_lock ▒ + 0.91% python libpython2.7.so.1.0 [.] insertdict ▒ + 0.89% python [kernel.kallsyms] [k] __audit_syscall_exit ▒ + 0.89% python libpython2.7.so.1.0 [.] vgetargs1 ▒ + 0.77% python [kernel.kallsyms] [k] release_pages ▒ + 0.76% python libpython2.7.so.1.0 [.] sre_charset ▒ + 0.74% python libpython2.7.so.1.0 [.] PyString_InternInPlace ▒ + 0.73% python libpython2.7.so.1.0 [.] PyString_FromStringAndSize ▒ + 0.73% python libpython2.7.so.1.0 [.] PyCFunction_Call ▒ + 0.71% python libpython2.7.so.1.0 [.] convertitem ▒ + 0.70% python libc-2.15.so [.] __memcmp_sse4_1 ▒ + 0.68% python libpython2.7.so.1.0 [.] vgetargskeywords ▒ + 0.68% python libc-2.15.so [.] malloc ▒ + 0.67% python libpython2.7.so.1.0 [.] PyDict_SetItem ▒ + 0.66% python [kernel.kallsyms] [k] avc_has_perm_flags ▒ + 0.62% python [kernel.kallsyms] [k] __audit_syscall_entry ▒ + 0.61% python libc-2.15.so [.] __memset_sse2 ▒ + 0.60% python libpython2.7.so.1.0 [.] PyCFunction_NewEx ▒ + 0.54% python libc-2.15.so [.] __strchr_sse42 ▒ + 0.52% python libpython2.7.so.1.0 [.] PyInt_FromLong ▒ + 0.51% python libpython2.7.so.1.0 [.] listiter_next ▒ + 0.49% python libpython2.7.so.1.0 [.] meth_dealloc ▒ + 0.48% python [kernel.kallsyms] [k] _raw_spin_lock_irqsave ▒ + 0.48% python libpython2.7.so.1.0 [.] PyObject_IsTrue ▒ + 0.47% python libc-2.15.so [.] free ▒ Clearly that doesn't by itself explain why these steps take so long, but may be useful information to use when looking at the code for those steps, or to someone who already has a good feel for the overall build process and understanding of the code. Another area that I started investigating was the do_compile phase of
building linux-yocto, since we have a way to fairly directly compare
the linux-yocto kernel compile with the straight 'make bzImage' of the
same code using the same configuration, which should provide a
relatively apples-to-apples comparison and might shed some light on
the differences between two things that are essentially doing the same
job.
From the previous high-level run, we found that there was a lot more
scheduler activity associated with the linux-yocto run as compared to
the straight 'make bzImage'.
I essentially ran the same thing again, but this time using all the
available tracepoint categories:
perf stat -a -e mac80211:* -e hda:* -e i915:* -e drm:* -e vsyscall:* -e raw_syscalls:* -e mce:* -e task:* -e printk:* -e irq:* -e timer:* -e signal:* -e workqueue:* -e rcu:* -e sched:* -e module:* -e power:* -e rpm:* -e oom:* -e vmscan:* -e kmem:* -e compaction:* -e writeback:* -e ext4:* -e jbd2:* -e block:* -e random:* -e scsi:* -e syscalls:* -e udp:* -e sock:* -e napi:* -e net:* -e skb:* sleep 90 &> perf-stat-compile.txt
I first did a 90 second 'baseline run' during a 'make bzImage' and
then the same run during the do_compile phase of 'bitbake linux-yocto'.
I then compared the values for all the tracepoints, and collected the
ones that had significant differences below:
make bzImage:
2,225,770 raw_syscalls:sys_exit [99.98%]
2,225,781 raw_syscalls:sys_enter [99.98%]
3,705 task:task_rename [99.98%]
3,657 task:task_newtask [99.98%]
411,472 irq:softirq_raise [99.98%]
411,504 irq:softirq_exit [99.98%]
411,552 irq:softirq_entry [99.98%]
25,341 irq:irq_handler_exit [99.98%]
25,341 irq:irq_handler_entry [99.98%]
0 timer:itimer_expire [99.98%]
9,222 timer:itimer_state [99.98%]
348,629 timer:hrtimer_cancel [99.98%]
215,305 timer:hrtimer_expire_exit [99.98%]
215,321 timer:hrtimer_expire_entry [99.98%]
348,766 timer:hrtimer_start [99.98%]
12,169 timer:hrtimer_init [99.98%]
51,374 timer:timer_cancel [99.98%]
44,591 timer:timer_expire_exit [99.98%]
44,597 timer:timer_expire_entry [99.98%]
51,391 timer:timer_start [99.98%]
15,313 timer:timer_init [99.98%]
2,059 signal:signal_deliver [99.98%]
3,656 signal:signal_generate [99.98%]
36,196 workqueue:workqueue_execute_end [99.98%]
36,197 workqueue:workqueue_execute_start [99.98%]
36,196 workqueue:workqueue_activate_work [99.98%]
36,197 workqueue:workqueue_queue_work [99.98%]
1,055,128 rcu:rcu_utilization [99.98%]
92,755,978,941 sched:sched_stat_runtime [99.98%]
17,525,690,593 sched:sched_stat_blocked [99.98%]
14,453,674,417 sched:sched_stat_iowait [99.98%]
13,147,209,679,772 sched:sched_stat_sleep [99.98%]
1,351,967,939 sched:sched_stat_wait [99.98%]
3,700 sched:sched_process_exec [99.98%]
3,657 sched:sched_process_fork [99.98%]
5,286 sched:sched_process_wait [99.98%]
0 sched:sched_wait_task [99.98%]
3,663 sched:sched_process_exit [99.98%]
3,663 sched:sched_process_free [99.98%]
30,537 sched:sched_migrate_task [99.98%]
196,010 sched:sched_switch [99.98%]
3,657 sched:sched_wakeup_new [99.98%]
95,012 sched:sched_wakeup [99.98%]
4,636 module:module_put [99.98%]
3,700 module:module_get [99.98%]
232,572 power:power_end [99.98%]
4,083 power:power_frequency [99.98%]
232,651 power:power_start [99.98%]
0 power:wakeup_source_deactivate [99.98%]
0 power:wakeup_source_activate [99.98%]
0 power:machine_suspend [99.98%]
4,084 power:cpu_frequency [99.98%]
465,588 power:cpu_idle [99.98%]
2,549,987 kmem:mm_page_pcpu_drain [99.98%]
2,601,044 kmem:mm_page_alloc_zone_locked [99.98%]
3,021,763 kmem:mm_page_alloc [99.98%]
2,911,389 kmem:mm_page_free_batched [99.98%]
2,978,189 kmem:mm_page_free [99.98%]
2,002,481 kmem:kmem_cache_free [99.98%]
2,946,599 kmem:kfree [99.98%]
14,283 kmem:kmem_cache_alloc_node [99.98%]
10,064 kmem:kmalloc_node [99.98%]
2,068,942 kmem:kmem_cache_alloc [99.98%]
663,137 kmem:kmalloc [99.98%]
1,483 writeback:writeback_single_inode [99.98%]
1,530 writeback:global_dirty_state [99.98%]
3,459 writeback:wbc_writepage [99.98%]
165,524 syscalls:sys_exit_mmap [99.98%]
165,524 syscalls:sys_enter_mmap [99.98%]
328 syscalls:sys_exit_set_tid_address [99.98%]
329 syscalls:sys_enter_set_tid_address [99.98%]
5,364 syscalls:sys_exit_wait4 [99.98%]
5,364 syscalls:sys_enter_wait4 [99.98%]
3,711 syscalls:sys_enter_exit_group [99.98%]
9,456 syscalls:sys_exit_setitimer [99.98%]
9,456 syscalls:sys_enter_setitimer [99.98%]
319 syscalls:sys_exit_gettid [99.98%]
319 syscalls:sys_enter_gettid [99.98%]
4,817 syscalls:sys_exit_getegid [99.98%]
4,817 syscalls:sys_enter_getegid [99.98%]
4,817 syscalls:sys_exit_getgid [99.98%]
4,817 syscalls:sys_enter_getgid [99.98%]
5,136 syscalls:sys_exit_geteuid [99.98%]
5,136 syscalls:sys_enter_geteuid [99.98%]
4,817 syscalls:sys_exit_getuid [99.98%]
4,817 syscalls:sys_enter_getuid [99.98%]
402 syscalls:sys_exit_getppid [99.98%]
402 syscalls:sys_enter_getppid [99.98%]
808 syscalls:sys_exit_getpid [99.98%]
808 syscalls:sys_enter_getpid [99.98%]
27,263 syscalls:sys_exit_rt_sigaction [99.98%]
27,263 syscalls:sys_enter_rt_sigaction [99.98%]
17,758 syscalls:sys_exit_rt_sigprocmask [99.98%]
17,758 syscalls:sys_enter_rt_sigprocmask [99.98%]
102,173 syscalls:sys_exit_munmap [99.98%]
102,173 syscalls:sys_enter_munmap [99.98%]
55,413 syscalls:sys_exit_brk [99.98%]
55,425 syscalls:sys_enter_brk [99.98%]
29,442 syscalls:sys_exit_mprotect [99.98%]
29,442 syscalls:sys_enter_mprotect [99.98%]
314,404 syscalls:sys_exit_close [99.98%]
314,412 syscalls:sys_enter_close [99.98%]
168 syscalls:sys_exit_openat [99.98%]
168 syscalls:sys_enter_openat [99.98%]
428,257 syscalls:sys_exit_open [99.98%]
428,257 syscalls:sys_enter_open [99.98%]
30 syscalls:sys_exit_chdir [99.98%]
30 syscalls:sys_enter_chdir [99.99%]
18,792 syscalls:sys_exit_access [99.99%]
18,815 syscalls:sys_enter_access [99.99%]
7,793 syscalls:sys_exit_writev [99.99%]
7,793 syscalls:sys_enter_writev [99.99%]
134,553 syscalls:sys_exit_write [99.99%]
134,553 syscalls:sys_enter_write [99.99%]
346,512 syscalls:sys_exit_read [99.99%]
346,522 syscalls:sys_enter_read [99.99%]
39,157 syscalls:sys_exit_lseek [99.99%]
39,157 syscalls:sys_enter_lseek [99.99%]
362 syscalls:sys_exit_readlink [99.99%]
362 syscalls:sys_enter_readlink [99.99%]
211,274 syscalls:sys_exit_newfstat [99.99%]
211,339 syscalls:sys_enter_newfstat [99.99%]
386 syscalls:sys_exit_newfstatat [99.99%]
386 syscalls:sys_enter_newfstatat [99.99%]
10,573 syscalls:sys_exit_newlstat [99.99%]
10,573 syscalls:sys_enter_newlstat [99.99%]
149,908 syscalls:sys_exit_newstat [99.99%]
150,058 syscalls:sys_enter_newstat [99.99%]
384 syscalls:sys_exit_pipe [99.99%]
384 syscalls:sys_enter_pipe [99.99%]
1 syscalls:sys_exit_mkdir [99.99%]
1 syscalls:sys_enter_mkdir [99.99%]
linux-yocto compile:
8,166,953 raw_syscalls:sys_exit [99.95%]
8,167,562 raw_syscalls:sys_enter [99.95%]
14,775 task:task_rename [99.95%]
14,781 task:task_newtask [99.95%]
1,375,724 irq:softirq_raise [99.95%]
1,375,960 irq:softirq_exit [99.95%]
1,376,104 irq:softirq_entry [99.95%]
8,437 irq:irq_handler_exit [99.95%]
8,437 irq:irq_handler_entry [99.95%]
3 timer:itimer_expire [99.95%]
1,094 timer:itimer_state [99.95%]
745,731 timer:hrtimer_cancel [99.95%]
744,204 timer:hrtimer_expire_exit [99.95%]
744,276 timer:hrtimer_expire_entry [99.95%]
746,132 timer:hrtimer_start [99.95%]
19,235 timer:hrtimer_init [99.95%]
111,240 timer:timer_cancel [99.95%]
99,770 timer:timer_expire_exit [99.95%]
99,792 timer:timer_expire_entry [99.95%]
111,306 timer:timer_start [99.95%]
35,086 timer:timer_init [99.95%]
11,814 signal:signal_deliver [99.95%]
14,891 signal:signal_generate [99.95%]
77,615 workqueue:workqueue_execute_end [99.95%]
77,623 workqueue:workqueue_execute_start [99.95%]
77,639 workqueue:workqueue_activate_work [99.95%]
77,647 workqueue:workqueue_queue_work [99.95%]
3,896,179 rcu:rcu_utilization [99.95%]
733,088,437,806 sched:sched_stat_runtime [99.95%]
97,337,624,822 sched:sched_stat_blocked [99.95%]
10,085,304,409 sched:sched_stat_iowait [99.95%]
10,474,055,515,466 sched:sched_stat_sleep [99.95%]
821,521,548,828 sched:sched_stat_wait [99.95%]
14,831 sched:sched_process_exec [99.95%]
14,841 sched:sched_process_fork [99.95%]
30,043 sched:sched_process_wait [99.95%]
0 sched:sched_wait_task [99.95%]
14,838 sched:sched_process_exit [99.95%]
14,838 sched:sched_process_free [99.95%]
50,003 sched:sched_migrate_task [99.95%]
577,752 sched:sched_switch [99.95%]
14,846 sched:sched_wakeup_new [99.95%]
294,897 sched:sched_wakeup [99.95%]
15,783 module:module_put [99.95%]
14,850 module:module_get [99.95%]
705 power:power_end [99.95%]
15 power:power_frequency [99.95%]
705 power:power_start [99.95%]
0 power:wakeup_source_deactivate [99.95%]
0 power:wakeup_source_activate [99.95%]
0 power:machine_suspend [99.95%]
15 power:cpu_frequency [99.95%]
1,411 power:cpu_idle [99.95%]
12,257,440 kmem:mm_page_pcpu_drain [99.95%]
12,508,463 kmem:mm_page_alloc_zone_locked [99.95%]
14,186,835 kmem:mm_page_alloc [99.95%]
13,719,141 kmem:mm_page_free_batched [99.95%]
13,960,572 kmem:mm_page_free [99.95%]
7,924,333 kmem:kmem_cache_free [99.95%]
11,021,671 kmem:kfree [99.95%]
17,803 kmem:kmem_cache_alloc_node [99.95%]
3,611 kmem:kmalloc_node [99.95%]
8,242,496 kmem:kmem_cache_alloc [99.95%]
2,651,134 kmem:kmalloc [99.95%]
6,251 writeback:writeback_single_inode [99.95%]
4,272 writeback:global_dirty_state [99.95%]
1,857 writeback:wbc_writepage [99.95%]
768,952 syscalls:sys_exit_mmap [99.96%]
768,977 syscalls:sys_enter_mmap [99.96%]
1,541 syscalls:sys_exit_set_tid_address [99.96%]
1,541 syscalls:sys_enter_set_tid_address [99.96%]
30,854 syscalls:sys_exit_wait4 [99.96%]
30,873 syscalls:sys_enter_wait4 [99.96%]
15,233 syscalls:sys_enter_exit_group [99.96%]
1,078 syscalls:sys_exit_setitimer [99.96%]
1,078 syscalls:sys_enter_setitimer [99.96%]
1,535 syscalls:sys_exit_gettid [99.96%]
1,536 syscalls:sys_enter_gettid [99.96%]
25,442 syscalls:sys_exit_getegid [99.96%]
25,442 syscalls:sys_enter_getegid [99.96%]
25,442 syscalls:sys_exit_getgid [99.96%]
25,442 syscalls:sys_enter_getgid [99.96%]
26,982 syscalls:sys_exit_geteuid [99.96%]
26,986 syscalls:sys_enter_geteuid [99.96%]
25,450 syscalls:sys_exit_getuid [99.96%]
25,455 syscalls:sys_enter_getuid [99.96%]
3,448 syscalls:sys_exit_getppid [99.96%]
3,448 syscalls:sys_enter_getppid [99.96%]
3,534 syscalls:sys_exit_getpid [99.96%]
3,534 syscalls:sys_enter_getpid [99.96%]
135,373 syscalls:sys_exit_rt_sigaction [99.96%]
135,373 syscalls:sys_enter_rt_sigaction [99.96%]
100,788 syscalls:sys_exit_rt_sigprocmask [99.96%]
100,788 syscalls:sys_enter_rt_sigprocmask [99.96%]
532,791 syscalls:sys_exit_munmap [99.97%]
532,820 syscalls:sys_enter_munmap [99.97%]
259,689 syscalls:sys_exit_brk [99.97%]
259,733 syscalls:sys_enter_brk [99.97%]
103,847 syscalls:sys_exit_mprotect [99.97%]
103,871 syscalls:sys_enter_mprotect [99.97%]
1,130,935 syscalls:sys_exit_close [99.97%]
1,131,259 syscalls:sys_enter_close [99.97%]
1,256 syscalls:sys_exit_openat [99.97%]
1,259 syscalls:sys_enter_openat [99.97%]
2,257,721 syscalls:sys_exit_open [99.97%]
2,257,799 syscalls:sys_enter_open [99.97%]
815 syscalls:sys_exit_chdir [99.97%]
815 syscalls:sys_enter_chdir [99.97%]
59,499 syscalls:sys_exit_access [99.97%]
59,504 syscalls:sys_enter_access [99.97%]
1,069 syscalls:sys_exit_writev [99.97%]
1,069 syscalls:sys_enter_writev [99.97%]
417,169 syscalls:sys_exit_write [99.97%]
417,293 syscalls:sys_enter_write [99.97%]
845,626 syscalls:sys_exit_read [99.97%]
845,868 syscalls:sys_enter_read [99.97%]
192,751 syscalls:sys_exit_lseek [99.97%]
192,751 syscalls:sys_enter_lseek [99.97%]
5,243 syscalls:sys_exit_readlink [99.97%]
5,244 syscalls:sys_enter_readlink [99.97%]
1,103,939 syscalls:sys_exit_newfstat [99.97%]
1,103,957 syscalls:sys_enter_newfstat [99.97%]
1,773 syscalls:sys_exit_newfstatat [99.97%]
1,773 syscalls:sys_enter_newfstatat [99.97%]
45,445 syscalls:sys_exit_newlstat [99.97%]
45,445 syscalls:sys_enter_newlstat [99.97%]
399,898 syscalls:sys_exit_newstat [99.97%]
399,898 syscalls:sys_enter_newstat [99.97%]
3,410 syscalls:sys_exit_pipe [99.97%]
3,410 syscalls:sys_enter_pipe [99.97%]
805 syscalls:sys_exit_mkdir [99.97%]
805 syscalls:sys_enter_mkdir [99.98%]
As mentioned previously and the above event counts seem to again show,
there appears to be a lot more scheduler activity in the linux-yocto
kernel compile than the straight 'make bzImage'. The data shows there
are indeed many more process-related events (fork/exec, wakeup_new,
etc), but there also seem to be a lot more schedule switches and
wakeups than expected.
If we do another more targeted perf run, this time sampling callchains
while using the sched:* tracepoints, looking at the sched:sched_wakeup
event, we see the following callchains seeming to contribute the most:
perf record -a -g -m 4096 -e sched:* sleep 90
- 78.06% cc1 [kernel.kallsyms] [k] ttwu_do_wakeup ◆
- ttwu_do_wakeup ▒
- 99.93% ttwu_do_activate.constprop.82 ▒
- try_to_wake_up ▒
- 58.20% default_wake_function ▒
- 97.63% autoremove_wake_function ▒
- 99.11% __wake_up_common ▒
- 88.84% __wake_up_sync_key ▒
- 99.71% pipe_write ▒
do_sync_write ▒
vfs_write ▒
sys_write ▒
tracesys ▒
+ __GI___libc_write ▒
+ 11.16% __wake_up ▒
+ 0.89% wake_bit_function ▒
+ 1.16% __wake_up_common ▒
+ 1.12% child_wait_callback ▒
+ 41.80% wake_up_process ▒
- 6.25% as [kernel.kallsyms] [k] ttwu_do_wakeup ▒
- ttwu_do_wakeup ▒
- 99.88% ttwu_do_activate.constprop.82 ▒
- try_to_wake_up ▒
- 60.48% default_wake_function ▒
- 76.97% autoremove_wake_function ▒
- 98.31% __wake_up_common ▒
- 87.20% __wake_up_sync_key ▒
pipe_read ▒
do_sync_read ▒
vfs_read ▒
sys_read ▒
tracesys ▒
+ __GI___libc_read ▒
+ 12.80% __wake_up ▒
+ 1.69% wake_bit_function ▒
+ 13.54% __wake_up_common ▒
+ 9.38% child_wait_callback ▒
+ 39.52% wake_up_process ▒
+ 4.23% sh [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 3.97% make [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 1.35% x86_64-poky-lin [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 1.20% fixdep [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 0.65% flush-8:0 [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 0.64% rm [kernel.kallsyms] [k] ttwu_do_wakeup ▒
+ 0.63% mv [kernel.kallsyms] [k] ttwu_do_wakeup ▒
Possibly the main reason for the higher number of sched_wakeup events
is due to increased use of pipes in the linux-yocto compile vs the
'make bzImage', and in fact we do see from the event counts between
the two a much larger number of pipe() system calls in the linux-yocto
case:
make bzImage:
384 syscalls:sys_exit_pipe [99.99%]
384 syscalls:sys_enter_pipe [99.99%]
linux-yocto:
3,410 syscalls:sys_exit_pipe [99.97%]
3,410 syscalls:sys_enter_pipe [99.97%]
We also see a couple other possibly interesting things, one that there
seems to be less iowaiting in the linux-yocto case, but much more
waiting in general, maybe again due to waiting on pipes.
make bzImage:
92,755,978,941 sched:sched_stat_runtime [99.98%]
17,525,690,593 sched:sched_stat_blocked [99.98%]
14,453,674,417 sched:sched_stat_iowait [99.98%]
13,147,209,679,772 sched:sched_stat_sleep [99.98%]
1,351,967,939 sched:sched_stat_wait [99.98%]
linux-yocto:
733,088,437,806 sched:sched_stat_runtime [99.95%]
97,337,624,822 sched:sched_stat_blocked [99.95%]
10,085,304,409 sched:sched_stat_iowait [99.95%]
10,474,055,515,466 sched:sched_stat_sleep [99.95%]
821,521,548,828 sched:sched_stat_wait [99.95%]
Finally, just as an unexpected data point, I added
INHIBIT_PACKAGE_STRIP = "1" to my local.conf, which removes the
additional step of stripping the binaries from the build.
I expected that removing the strip step would decrease the build time,
but in fact it (verified over several runs) added a couple minutes to
the build time instead.
Apparently by turning this off the binaries become larger, so the
packaging steps apparently become larger in consequence (actually
looking at the timings, see attached screenshot
pychart-linux-yocto-rpm-nostrip.png, the additional time seems to be
going into the do_package_write task). Again, this seems to be some
kind of amplified inefficiency in the packaging step - even if there
is double the number of bytes in this case, increasing the build time
by two minutes for that seems out of line.
with INHIBIT_PACKAGE_STRIP = "1"
PACKAGE_CLASSES ?= "package_rpm"
real 19m19.010s
user 24m5.982s
sys 5m46.152s
Created attachment 945 [details]
linux-yocto pybootchart (nostrip)
I wanted to get some basic idea of which tasks to focus performance measurements on so I added some timestamping code to the bitbake log functions and also added some bbnote calls to do_package, to get a bit more breakdown there. Below are the results of the timings.
As to the package choices, I chose python and perl since they seemed to be relatively 'normal' recipes that take awhile to build, ltp because it seems to have a longer than normal package phase, and the kernel because it's critical that we bring down the time for that for workflow reasons.
The one thing that's obvious is that packaging (do_package and do_package_write) take a long time relative to everything else. The below recipes for the most part have almost 60% of their build time taken up by packaging, and for ltp it's 70%. So apparently the place to focus on initially for performance improvements would be what happens in do_package and do_package_write.
It also makes me think that there's probably nothing inherently inefficient in the way the build system works and am wondering about whether spending too much time to globally optimize is worth the effort - my sense is that if you removed the packaging phase completely, you'd be pretty close to the 'fast' build times advertised by other build systems that don't do any packaging such as Buildroot. Buildroot reports a build time of about 30 minutes for an x86 target with X - removing the packaging phase from Yocto would probably bring down the build time for sato to about 45 minutes, which is close to the same thing for buildroot as a rough estimate (Yocto may have more packages in its sato image than the analagous image for buildroot - we can't tell without doing a detailed comparison, and this is all just ballbark anyway).
I wanted to try the 'tar' packaging as possibly a better baseline without the overhead of the other packaging schemes (PACKAGE_CLASSES ?= "package_tar") but apparently it doesn't work on its own and needs to be added to one of the others).
----
[trz@empanada build]$ time bitbake python
real 5m34.883s
user 3m32.879s
sys 1m21.502s
do_configure: 32 secs
10:46:00
10:46:32
do_compile: 48 secs
10:46:32
10:47:20
do_install: 50 secs (a lot of the install is compiling .py files)
10:47:20
10:48:10
do_package: 2:20 min
10:48:11
split_and_strip_files(): 15 s
10:48:12
10:48:27
populate_packages: 15 s
10:48:28
10:48:43
package_do_filedeps: 1:17 min
10:48:43
10:50:00
package_do_shlibs: 7 s
10:50:00
10:50:07
do_package_qa: 5 s
10:50:10
10:50:15
sstate_task_postfunc: 16s
10:50:15
sstate_create_package: 9 s
10:50:22
10:50:31
10:50:31
10:50:31
do_package_write: 50 s
10:50:31
10:51:21
Total packaging time: 3:10 min / 5:35 min = 57%
----
[trz@empanada build]$ time bitbake linux-yocto
real 19m49.871s
user 24m9.529s
sys 7m43.978s
do_kernel_checkout: 6 sec
12:11:24
12:11:30
do_kernel_configme: 30 sec
12:12:21
12:12:51
do_kernel_configcheck: 7 sec
12:13:35
12:13:42
do_patch: 49 sec
12:11:31
12:12:20
do_configure: 44 sec
12:12:51
12:13:35
do_compile: 2:08 min
12:13:42
12:15:50
do_compile_kernelmodules: 37 sec
12:15:50
12:16:27
do_install: 3:14 min
12:16:27
12:19:41
do_package: 7:39 min
12:19:42
perform_packagecopy: 9 sec
12:19:42
12:19:51
split_and_strip_files: 13 sec
12:19:51
12:20:04
populate_packages: 2:36 min
12:20:05
12:22:41
package_do_filedeps: 1:46 min
12:22:41
12:24:27
package_do_shlibs: 18 sec
12:24:27
12:24:45
package_do_pkgconfig: 8 sec
12:24:45
12:24:53
emit_pkgdata: 10 sec
12:24:53
12:25:03
do_package_qa: 24 sec
12:25:03
12:25:27
sstate_task_postfunc: 1:54 min
12:25:27
sstate_create_package: 57 sec
12:26:24
12:27:21
12:27:21
12:27:21
do_package_write_rpm: 3:43 min
12:27:21
BUILDSPEC: 3:27 min
12:27:32: Executing shell function BUILDSPEC
12:30:59: Shell function BUILDSPEC finished
12:31:04
do_populate_sysroot: 23 sec
12:19:42
12:20:05
Total packaging time = 11:22 / 19:50 min = 57%
----
[trz@empanada build]$ time bitbake ltp
real 6m9.727s
user 4m58.636s
sys 2m48.566s
do_configure: 14 sec
14:12:56
14:13:10
do_compile: 51 sec
14:13:10
14:14:01
do_install: 35 sec
14:14:01
14:14:36
do_package: 3:09 min
14:14:36
perform_packagecopy: 5 sec
14:14:36
14:14:41
populate_packages: 29 sec
14:14:41
14:15:10
package_do_filedeps: 16 sec
14:15:10
14:15:26
package_do_shlibs: 1:03 min
14:15:26
14:16:29
do_package_qa: 45 sec
14:16:31
14:17:16
sstate_task_postfunc: 29 sec
14:17:16
sstate_create_package: 18 sec
14:17:27
14:17:45
14:17:45
14:17:45
do_package_write_rpm: 1:10 min
14:17:45
BUILDSPEC: 1:06 min
14:17:47.297985: Executing shell function BUILDSPEC
14:18:53.909804: Shell function BUILDSPEC finished
14:18:55
Total packaging time = 4:19 / 6:10 min = 70%
----
[trz@empanada build]$ time bitbake perl
real 8m53.452s
user 5m13.794s
sys 2m40.222s
do_compile: 3:19 min
14:25:14
14:28:33
do_install: 26 sec
14:28:34
14:29:00
do_package: 2:29 min
14:29:01
split_and_strip_files: 15 sec
14:29:03
14:29:18
populate_packages: 23 sec
14:29:18
14:29:41
package_do_filedeps: 44 sec
14:29:41
14:30:25
package_do_shlibs: 8 sec
14:30:25
14:30:33
emit_pkgdata: 17 sec
14:30:36
14:30:53
do_package_qa: 9 sec
14:30:53
14:31:02
sstate_task_postfunc: 28 sec
14:31:02
sstate_create_package: 12 sec
14:31:17
14:31:29
14:31:30
14:31:30
do_package_write_rpm: 2:18 min
14:31:30
BUILDSPEC: 2:07 min
14:31:38: Executing shell function BUILDSPEC
14:33:45: Shell function BUILDSPEC finished
14:33:48
Total packaging time = 4:47 / 8:53 min = 55%
----
Also, for the linux-yocto test, trying to figure out why do_install takes so long, when it happens almost instantaneously by hand, to see if it's a good case to analyze, not really - turns out mostly the copy and pruning of the tree.
linux yocto do_install:
The actual modules_install is very fast:
NOTE 15:52:42: start modules_install
NOTE 15:52:44: end modules_install
The copy of the entire source tree takes 1:45 min:
NOTE 15:52:44: start install 4
bbnote "start install 4"
#
# Copy the entire source tree. In case an external build directory is
# used, copy the build directory over first, then copy over the source
# dir. This ensures the original Makefiles are used and not the
# redirecting Makefiles in the build directory.
#
# work and sysroots can be on different partitions, so we can't rely on
# hardlinking, unfortunately.
#
cp -fR * $kerneldir
cp .config $kerneldir
if [ "${S}" != "${B}" ]; then
cp -fR ${S}/* $kerneldir
fi
install -m 0644 ${KERNEL_OUTPUT} $kerneldir/${KERNEL_IMAGETYPE}
install -m 0644 System.map $kerneldir/System.map-${KERNEL_VERSION}
NOTE 15:54:29: start install 5
cleaning and removing files not needed takes 1:41 min:
NOTE 15:54:29: start install 5
bbnote "start install 5"
#
# Clean and remove files not needed for building modules.
# Some distributions go through a lot more trouble to strip out
# unecessary headers, for now, we just prune the obvious bits.
#
# We don't want to leave host-arch binaries in /sysroots, so
# we clean the scripts dir while leaving the generated config
# and include files.
#
oe_runmake -C $kerneldir CC="${KERNEL_CC}" LD="${KERNEL_LD}" clean
make -C $kerneldir _mrproper_scripts
find $kerneldir -path $kerneldir/lib -prune -o -path $kerneldir/tools -prune -o -path $ker\
neldir/scripts -prune -o -name "*.[csS]" -exec rm '{}' \;
find $kerneldir/Documentation -name "*.txt" -exec rm '{}' \;
NOTE 15:56:10: start install 6
Tom, please update the milestone. From Tom:
> I'll plan to do another set of testing passes then close it. It can be
> reopened if necessary during 1.5 i.e. if more work needs to be done in
> this area.
I need to do another set of test runs for this, but it shouldn't be blocking anything and should be changed from Medium+ to something less. Moving to 1.5. Overall build performance is a priority for the project. It does fall behind hardware enabled for the kernel team. Marking as Medium. We do need a way to ensure some well defined bit of this is done, probably for every release. Coming up with documentation on how to do this and then making it part of the QA tests might be a way to free up Tom and still ensure this happens. Note that there are sanity checks on file paths implemented in rpmbuild that go as some power of the number of files (and there are *lots* of files in a kernel package). Disabling the sanity checks is mostly simple. The better fix is to parallelize the payload compression in rpmbuild. (this is essentially the same as gzip -> pigz but rpmbuild uses the zlib library, not gzip). Running callgrind on rpmbuild should show the hot spots. Closing unless there's something specific left to do here. |
It could be worthwhile to apply the Linux profiling and tracing tools to builds see if/where performance improvements can be made. I'm opening this bug mainly as a place to track the results of various tests, as well as a means to solicit input or ideas on what might be useful areas to look into. As a start, I used a couple different variations on 'perf stat' and 'time' to get some overall statistics for a linux-yocto build/compile vs a straight kernel compile (make bzImage;make modules) outside of yocto. This is perhaps not a great example, as the kernel may be a special case, but this is just a start and amongst the many other things I try will be comparisons using other packages, etc. So to start with, here's the timing of a couple of runs of a linux-yocto build. The first is just a straight perf stat also using 'time': [trz@empanada build]$ time perf stat bitbake linux-yocto Performance counter stats for 'bitbake linux-yocto': 2106743.861387 task-clock # 1.760 CPUs utilized 9,444,467 context-switches # 0.004 M/sec 3,543,746 CPU-migrations # 0.002 M/sec 62,802,945 page-faults # 0.030 M/sec 5,689,690,569,905 cycles # 2.701 GHz 3,726,771,577,960 stalled-cycles-frontend # 65.50% frontend cycles idle <not supported> stalled-cycles-backend 4,895,596,907,727 instructions # 0.86 insns per cycle # 0.76 stalled cycles per insn 1,078,507,550,210 branches # 511.931 M/sec 32,395,063,666 branch-misses # 3.00% of all branches 1197.262258260 seconds time elapsed real 19m57.267s user 24m52.728s sys 6m37.550s So, about 20 minutes total. To get some more quick information related to the scheduler, since there seems to be a lot of context switching, here's another run using the sched:* tracepoints: Performance counter stats for 'bitbake linux-yocto': 0 sched:sched_pi_setprio 2,440,869,343,508 sched:sched_stat_runtime 587,812,551,350 sched:sched_stat_blocked 105,101,978,804 sched:sched_stat_iowait 45,181,473,663,780 sched:sched_stat_sleep 1,572,707,964,734 sched:sched_stat_wait 78,517 sched:sched_process_exec 94,270 sched:sched_process_fork 170,073 sched:sched_process_wait 0 sched:sched_wait_task 94,270 sched:sched_process_exit 32,420 sched:sched_process_free 3,399,186 sched:sched_migrate_task 9,599,171 sched:sched_switch 188,540 sched:sched_wakeup_new 18,333,540 sched:sched_wakeup 0 sched:sched_kthread_stop_ret 0 sched:sched_kthread_stop 1389.485424509 seconds time elapsed real 23m9.845s user 25m37.492s sys 8m30.657s This breaks things down a bit further so we can see some of the scheduler events such as sched_wakeups which also seems very high. So that may or may not be interesting, we don't have anything to compare it with (though it's useful information we can use to see how much of that work is related to the actual meat of the build, the compile). Let's try to measure something that we can use in a more apples-to-apples comparison, just the kernel and modules compile. Here's the results of just the kernel compile: Performance counter stats for 'bitbake -c compile -f linux-yocto': 0 sched:sched_pi_setprio 853,297,586,572 sched:sched_stat_runtime 212,202,623,762 sched:sched_stat_blocked 14,106,497,975 sched:sched_stat_iowait 25,813,089,471,923 sched:sched_stat_sleep 1,306,320,831,322 sched:sched_stat_wait 18,934 sched:sched_process_exec 20,387 sched:sched_process_fork 40,405 sched:sched_process_wait 0 sched:sched_wait_task 20,388 sched:sched_process_exit 15,736 sched:sched_process_free 51,239 sched:sched_migrate_task 637,358 sched:sched_switch 40,774 sched:sched_wakeup_new 740,869 sched:sched_wakeup 0 sched:sched_kthread_stop_ret 0 sched:sched_kthread_stop 132.892074456 seconds time elapsed real 2m13.085s user 13m8.586s sys 1m3.700s Performance counter stats for 'bitbake -c compile_kernelmodules -f linux-yocto': 0 sched:sched_pi_setprio 277,188,608,215 sched:sched_stat_runtime 116,763,216,437 sched:sched_stat_blocked 3,824,407,918 sched:sched_stat_iowait 4,652,690,392,700 sched:sched_stat_sleep 408,866,164,744 sched:sched_stat_wait 12,729 sched:sched_process_exec 13,189 sched:sched_process_fork 24,152 sched:sched_process_wait 0 sched:sched_wait_task 13,190 sched:sched_process_exit 9,767 sched:sched_process_free 31,943 sched:sched_migrate_task 285,593 sched:sched_switch 26,378 sched:sched_wakeup_new 386,157 sched:sched_wakeup 0 sched:sched_kthread_stop_ret 0 sched:sched_kthread_stop 44.482756558 seconds time elapsed So, about 3 minutes for the kernel + modules compile, compared with the 20 minutes for the entire linux-yocto build, where clearly most of the time is taken up by something other than that. The 3 minutes for the kernel + modules compile seems really low, but let's just compare it with the same thing outside of the build system i.e. make bzImage; make modules: Performance counter stats for 'make bzImage': 0 sched:sched_pi_setprio 74,975,679,732 sched:sched_stat_runtime 43,780,057,223 sched:sched_stat_blocked 37,812,851,094 sched:sched_stat_iowait 1,360,014,835,150 sched:sched_stat_sleep 2,338,127,596 sched:sched_stat_wait 13,893 sched:sched_process_exec 15,180 sched:sched_process_fork 26,291 sched:sched_process_wait 0 sched:sched_wait_task 15,181 sched:sched_process_exit 954 sched:sched_process_free 33,277 sched:sched_migrate_task 73,774 sched:sched_switch 30,360 sched:sched_wakeup_new 92,292 sched:sched_wakeup 0 sched:sched_kthread_stop_ret 0 sched:sched_kthread_stop 125.064294191 seconds time elapsed real 2m5.350s user 0m44.009s sys 0m29.540s Performance counter stats for 'make modules': 0 sched:sched_pi_setprio 33,047,891,608 sched:sched_stat_runtime 23,493,459,972 sched:sched_stat_blocked 21,909,173,672 sched:sched_stat_iowait 531,342,927,976 sched:sched_stat_sleep 976,222,113 sched:sched_stat_wait 6,952 sched:sched_process_exec 7,329 sched:sched_process_fork 12,040 sched:sched_process_wait 0 sched:sched_wait_task 7,330 sched:sched_process_exit 685 sched:sched_process_free 15,986 sched:sched_migrate_task 30,449 sched:sched_switch 14,658 sched:sched_wakeup_new 38,648 sched:sched_wakeup 0 sched:sched_kthread_stop_ret 0 sched:sched_kthread_stop 58.995530753 seconds time elapsed real 0m59.183s user 0m17.793s sys 0m14.662s So, the time for the compile is about the same outside of the build system, but one thing that is a noticeable difference between two is that the oe-core kernel compile has about an order of magnitude more sched_switch and sched_wakeup events than the straight make bzImage. As mentioned, I'll investigate this some more when I get the time - I expect this to be an ongoing process that I'll record here.