Re: [RFC PATCH v2] ftrace: support very early function tracing

[Abderrahmane Benbachir]

I implemented the ring_buffer_set_clock solution and I have some questions.


void __init ftrace_early_fill_ringbuffer(void *data)
{
...
	ring_buffer_set_clock(tr->trace_buffer.buffer, early_trace_clock);
	preempt_disable_notrace();
	for (i = 0; i < vearly_entries_count; i++) {
		entry = &ftrace_vearly_entries[i];

		early_timestamp = entry->clock;

		trace_function(tr, entry->ip, entry->parent_ip, 0, 0);
	}
	preempt_enable_notrace();

        /* TODO: should set the previous clock */
	ring_buffer_set_clock(tr->trace_buffer.buffer, trace_clock_local);

I need also to save the current clock before calling  
"ring_buffer_set_clock()", is there
a way to get the current clock or to set the clock from tr->clock_id ?


There is one thing happening when using the trace_clock_local instead  
of rdtsc.

I added different kernel params to trigger the issue :

When using entry->clock = trace_clock_local():

kernel param "ftrace_vearly ftrace_filter=*_init"


[    0.312179]   <idle>-0       0dp..    0us : boot_cpu_init <-start_kernel
...
[    0.320280]   <idle>-0       0dp..    0us : numa_init <-x86_numa_init
[    0.320673]   <idle>-0       0dp..    0us : dummy_numa_init <-numa_init
[    0.321082]   <idle>-0       0dp..    6us : paging_init <-setup_arch
[    0.321471]   <idle>-0       0dp..    9us : sparse_init <-paging_init
[    0.321867]   <idle>-0       0dp.. 1174us : zone_sizes_init <-paging_init
[    0.322283]   <idle>-0       0dp.. 1201us : lruvec_init  
<-free_area_init_node
[    0.322714]   <idle>-0       0dp.. 1524us : acpi_boot_init <-setup_arch
[    0.323120]   <idle>-0       0dp.. 1595us : sfi_init <-setup_arch
[    0.323500]   <idle>-0       0dp.. 1601us : kvm_guest_init <-setup_arch
[    0.323904]   <idle>-0       0dp.. 1623us : mcheck_init <-setup_arch
[    0.324293]   <idle>-0       0dp.. 1623us : mcheck_intel_therm_init  
<-mcheck_init
[    0.324772]   <idle>-0       0dp.. 1724us : boot_cpu_state_init  
<-start_kernel
[    0.325259]   <idle>-0       0dp.. 1724us : kvm_guest_cpu_init  
<-kvm_smp_prepare_boot_cpu
[    0.325789]   <idle>-0       0dp.. 1733us : kvm_spinlock_init  
<-kvm_smp_prepare_boot_cpu
[    0.326300]   <idle>-0       0dp.. 1733us :  
build_all_zonelists_init <-build_all_zonelists
[    0.326820]   <idle>-0       0dp.. 1738us : page_alloc_init <-start_kernel
[    0.327252]   <idle>-0       0dp.. 1906us : jump_label_init <-start_kernel
[    0.327673]   <idle>-0       0dp.. 4913us : pidhash_init <-start_kernel
[    0.328076]   <idle>-0       0dp.. 4917us : trap_init <-start_kernel
[    0.328466]   <idle>-0       0dp.. 4927us : kvm_apf_trap_init <-trap_init
[    0.328877]   <idle>-0       0dp.. 4928us : mem_init <-start_kernel
[    0.329263]   <idle>-0       0dp.. 4930us : gart_iommu_hole_init  
<-pci_iommu_alloc
[    0.329745]   <idle>-0       0dp.. 5129us : kmem_cache_init <-start_kernel
[    0.330162]   <idle>-0       0dp.. 5300us : vmalloc_init <-start_kernel


kernel param "ftrace=function ftrace_vearly ftrace_filter=*_init"

[    0.315455]   <idle>-0       0dp.. 18446744073666366us :  
boot_cpu_init <-start_kernel
...
[    0.338102]   <idle>-0       0dp.. 18446744073671436us : trap_init  
<-start_kernel
[    0.338584]   <idle>-0       0dp.. 18446744073671446us :  
kvm_apf_trap_init <-trap_init
[    0.339089]   <idle>-0       0dp.. 18446744073671447us : mem_init  
<-start_kernel
[    0.339564]   <idle>-0       0dp.. 18446744073671449us :  
gart_iommu_hole_init <-pci_iommu_alloc
[    0.340111]   <idle>-0       0dp.. 18446744073671635us :  
kmem_cache_init <-start_kernel
[    0.340622]   <idle>-0       0dp.. 18446744073671775us :  
vmalloc_init <-start_kernel
> > > > > > > > > > > > > > > >   function tracing starts here   <<<<<<<<<<<<<<<<<<<<<<<<<<
[    0.341119]   <idle>-0       0dp.1 48004us : sched_init <-start_kernel
[    0.341520]   <idle>-0       0dp.1 48005us : wait_bit_init <-sched_init
[    0.341926]   <idle>-0       0dp.1 48007us : hrtimer_init  
<-init_rt_bandwidth
[    0.342359]   <idle>-0       0dp.1 48007us : __hrtimer_init <-hrtimer_init
[    0.342779]   <idle>-0       0dp.1 48007us : cpudl_init <-init_rootdomain
[    0.343196]   <idle>-0       0dp.1 48008us : cpupri_init <-init_rootdomain
[    0.343618]   <idle>-0       0dp.1 48014us : autogroup_init <-sched_init


When using entry->clock = rdtsc() [working well]:

kernel param "ftrace=function ftrace_vearly ftrace_filter=*_init"

[    0.314067]   <idle>-0       0dp.. 154207us : boot_cpu_init <-start_kernel
...
[    0.333397]   <idle>-0       0dp.. 180362us : mem_init <-start_kernel
[    0.333806]   <idle>-0       0dp.. 180365us : gart_iommu_hole_init  
<-pci_iommu_alloc
[    0.334330]   <idle>-0       0dp.. 180652us : kmem_cache_init  
<-start_kernel
[    0.334760]   <idle>-0       0dp.. 180810us : vmalloc_init <-start_kernel
> > > > > > > > > > > > > > > >   function tracing starts here   <<<<<<<<<<<<<<<<<<<<<<<<<<
[    0.335225]   <idle>-0       0dp.1 180810us : sched_init <-start_kernel
[    0.335626]   <idle>-0       0dp.1 180810us : wait_bit_init <-sched_init
[    0.336015]   <idle>-0       0dp.1 180810us : hrtimer_init  
<-init_rt_bandwidth
[    0.336500]   <idle>-0       0dp.1 180810us : __hrtimer_init <-hrtimer_init
[    0.336981]   <idle>-0       0dp.1 180810us : cpudl_init <-init_rootdomain
[    0.337381]   <idle>-0       0dp.1 180810us : cpupri_init <-init_rootdomain