Re: FTRACE: regression in 31-rc7

[Gregory Haskins <gregory.haskins@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 7412 bytes --]

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 267 bytes --]