Messages in this thread | | | Date | Thu, 27 Aug 2009 12:58:40 -0400 | From | Gregory Haskins <> | Subject | Re: FTRACE: regression in 31-rc7 |
| |
Ingo Molnar wrote: > * Gregory Haskins <gregory.haskins@gmail.com> wrote: > >> Hi Steve, >> >> I just moved from -rc6 to -rc7, and I noticed that the >> function-graph tracer suddenly stopped working properly: I do not >> see any output from seeming most things except a handful of >> interrupt related events. I currently believe it may be an issue >> with tracing modules. >> >> I haven't had a chance to bisect yet, but I did confirm that >> reverting the -rc7 merge restores the previous tracer behavior. >> Any help/pointers appreciated. > > Works fine here (using -rc7 based -tip): > > 11) | sys_munmap() { > 11) | profile_munmap() { > 11) | blocking_notifier_call_chain() { > 11) 0.170 us | __blocking_notifier_call_chain(); > 11) 0.480 us | } > 11) 0.799 us | } > 11) | down_write() { > 11) 0.146 us | _cond_resched(); > 11) 0.146 us | _spin_lock_irq(); > 11) 0.754 us | } > 11) | do_munmap() { > 11) 0.144 us | test_ti_thread_flag(); > 11) 0.144 us | test_ti_thread_flag(); > 11) 0.164 us | find_vma(); > 11) 0.156 us | arch_unmap_area_topdown(); > 11) | unmap_region() { > 11) | lru_add_drain() { > 11) | ____pagevec_lru_add() { > 11) 0.153 us | _spin_lock_irq(); > 11) 0.145 us | __inc_zone_state(); > 11) | __inc_zone_state() { > 11) 0.144 us | __inc_zone_state(); > 11) 0.146 us | __inc_zone_state(); > 11) 0.145 us | __inc_zone_state(); > 11) 0.223 us | release_pages(); > 11) 2.463 us | } > 11) 2.795 us | } > 11) | unmap_vmas() { > 11) | unmap_page_range() { > 11) 0.144 us | pgd_none_or_clear_bad(); > 11) 0.145 us | pud_none_or_clear_bad(); > 11) 0.154 us | pmd_none_or_clear_bad(); > 11) | zap_pte_range() { > 11) 0.145 us | _spin_lock(); > 11) 0.168 us | vm_normal_page(); > 11) 0.143 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.150 us | __dec_zone_state(); > 11) 0.441 us | } > 11) 0.748 us | } > 11) 0.149 us | vm_normal_page(); > 11) 0.146 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.148 us | __dec_zone_state(); > 11) 0.439 us | } > 11) 0.748 us | } > 11) 0.144 us | vm_normal_page(); > 11) 0.148 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.148 us | __dec_zone_state(); > 11) 0.438 us | } > 11) 0.731 us | } > 11) 0.144 us | vm_normal_page(); > 11) 0.146 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.146 us | __dec_zone_state(); > 11) 0.437 us | } > 11) 0.733 us | } > 11) 0.143 us | vm_normal_page(); > 11) 0.148 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.147 us | __dec_zone_state(); > 11) 0.438 us | } > 11) 0.731 us | } > 11) 0.144 us | vm_normal_page(); > 11) 0.146 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.146 us | __dec_zone_state(); > 11) 0.436 us | } > 11) 0.732 us | } > 11) 0.143 us | vm_normal_page(); > 11) 0.146 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.147 us | __dec_zone_state(); > 11) 0.435 us | } > 11) 0.751 us | } > 11) 0.142 us | vm_normal_page(); > 11) 0.146 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.146 us | __dec_zone_state(); > 11) 0.438 us | } > 11) 0.733 us | } > 11) 0.143 us | vm_normal_page(); > 11) 0.145 us | mark_page_accessed(); > 11) | page_remove_rmap() { > 11) | __dec_zone_page_state() { > 11) 0.145 us | __dec_zone_state(); > 11) 0.434 us | } > 11) 0.731 us | } > 11) + 14.220 us | } > 11) + 15.442 us | } > 11) + 15.750 us | } > 11) | free_pgtables() { > > so it would be nice if you sent a config and a precise description > of what you did to see the weirdness - in case others have trouble > reproducing it as well.
Yeah, sorry. I should have provided more detail. Usually I'd hit Steve up directly on IRC and he'd point me in the right direction, but he wasn't online today. But I guess the "IRC terseness" carried on to the mail. ;). I guess I was wondering if anyone else had seen this before digging in.
I digress.
All I was doing was enabling the basic function-graph tracer, enabling the tracer, run a test, stopping the tracer, and taking a look at the "trace" output by grepping for functions that I knew should have hit.
In -rc7, grep turns up empty and I can't seem to find evidence that any of my code was hit, even though other utilities (like top) indicated my code was indeed running (I could see kthreads belonging to my module use cpu, for instance). In addition, the test passes so its not like it may have skipped over the function I was looking for. Its just not being traced for some reason.
Reverting back to -rc6 and a simple recompile + repeat of the same steps indeed restored the behavior that I was accustomed to.
I noticed that both the output that I could observe, plus the output you provide above seem to be core-kernel related functions. I know all the traces I was looking for were module related. Therefore, I suspect that somehow module code (or at least, my module code) is not being instrumented for some reason.
Kind Regards, -Greg
[unhandled content-type:application/pgp-signature] | |