Messages in this thread | | | Date | Wed, 08 Nov 2017 18:44:39 +0000 | From | Abderrahmane Benbachir <> | Subject | Re: [RFC PATCH v2] ftrace: support very early function tracing |
| |
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
| |