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

[Steven Rostedt <rostedt@goodmis.org>]

On Wed, 08 Nov 2017 18:44:39 +0000
Abderrahmane Benbachir <abderrahmane.benbachir@polymtl.ca> wrote:

> 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 ?

No, but we could add one, although it is not really necessary. This is
why I just defaulted to what it is set to at the start anyway. It's
hard coded to trace_clock_local now, and it's only changed via the
command line parameter after this code is run.

> 
> 
> 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
> 

I'd have to see the code to figure this out.

-- Steve

> 
> 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
>