From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752419AbdKHTJg (ORCPT ); Wed, 8 Nov 2017 14:09:36 -0500 Received: from mail.kernel.org ([198.145.29.99]:52666 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751975AbdKHTJf (ORCPT ); Wed, 8 Nov 2017 14:09:35 -0500 DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org C9B38217C0 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=goodmis.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=rostedt@goodmis.org Date: Wed, 8 Nov 2017 14:09:32 -0500 From: Steven Rostedt To: Abderrahmane Benbachir Cc: linux-kernel@vger.kernel.org, mingo@redhat.com, peterz@infradead.org, mathieu.desnoyers@efficios.com Subject: Re: [RFC PATCH v2] ftrace: support very early function tracing Message-ID: <20171108140932.2b6b5779@gandalf.local.home> In-Reply-To: <20171108184439.Horde.Upzg5-g409vJdseHTmBvZEN@www.imp.polymtl.ca> References: <1510098245.14960.3.camel@polymtl.ca> <20171107211706.328d7dd0@gandalf.local.home> <20171108155640.Horde.pdOYcdS3_Zox7UhqM007fgC@www.imp.polymtl.ca> <20171108184439.Horde.Upzg5-g409vJdseHTmBvZEN@www.imp.polymtl.ca> X-Mailer: Claws Mail 3.14.0 (GTK+ 2.24.31; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Wed, 08 Nov 2017 18:44:39 +0000 Abderrahmane Benbachir 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] -0 0dp.. 0us : boot_cpu_init <-start_kernel > ... > [ 0.320280] -0 0dp.. 0us : numa_init <-x86_numa_init > [ 0.320673] -0 0dp.. 0us : dummy_numa_init <-numa_init > [ 0.321082] -0 0dp.. 6us : paging_init <-setup_arch > [ 0.321471] -0 0dp.. 9us : sparse_init <-paging_init > [ 0.321867] -0 0dp.. 1174us : zone_sizes_init <-paging_init > [ 0.322283] -0 0dp.. 1201us : lruvec_init > <-free_area_init_node > [ 0.322714] -0 0dp.. 1524us : acpi_boot_init <-setup_arch > [ 0.323120] -0 0dp.. 1595us : sfi_init <-setup_arch > [ 0.323500] -0 0dp.. 1601us : kvm_guest_init <-setup_arch > [ 0.323904] -0 0dp.. 1623us : mcheck_init <-setup_arch > [ 0.324293] -0 0dp.. 1623us : mcheck_intel_therm_init > <-mcheck_init > [ 0.324772] -0 0dp.. 1724us : boot_cpu_state_init > <-start_kernel > [ 0.325259] -0 0dp.. 1724us : kvm_guest_cpu_init > <-kvm_smp_prepare_boot_cpu > [ 0.325789] -0 0dp.. 1733us : kvm_spinlock_init > <-kvm_smp_prepare_boot_cpu > [ 0.326300] -0 0dp.. 1733us : > build_all_zonelists_init <-build_all_zonelists > [ 0.326820] -0 0dp.. 1738us : page_alloc_init <-start_kernel > [ 0.327252] -0 0dp.. 1906us : jump_label_init <-start_kernel > [ 0.327673] -0 0dp.. 4913us : pidhash_init <-start_kernel > [ 0.328076] -0 0dp.. 4917us : trap_init <-start_kernel > [ 0.328466] -0 0dp.. 4927us : kvm_apf_trap_init <-trap_init > [ 0.328877] -0 0dp.. 4928us : mem_init <-start_kernel > [ 0.329263] -0 0dp.. 4930us : gart_iommu_hole_init > <-pci_iommu_alloc > [ 0.329745] -0 0dp.. 5129us : kmem_cache_init <-start_kernel > [ 0.330162] -0 0dp.. 5300us : vmalloc_init <-start_kernel > > > kernel param "ftrace=function ftrace_vearly ftrace_filter=*_init" > > [ 0.315455] -0 0dp.. 18446744073666366us : > boot_cpu_init <-start_kernel > ... > [ 0.338102] -0 0dp.. 18446744073671436us : trap_init > <-start_kernel > [ 0.338584] -0 0dp.. 18446744073671446us : > kvm_apf_trap_init <-trap_init > [ 0.339089] -0 0dp.. 18446744073671447us : mem_init > <-start_kernel > [ 0.339564] -0 0dp.. 18446744073671449us : > gart_iommu_hole_init <-pci_iommu_alloc > [ 0.340111] -0 0dp.. 18446744073671635us : > kmem_cache_init <-start_kernel > [ 0.340622] -0 0dp.. 18446744073671775us : > vmalloc_init <-start_kernel > >>>>>>>>>>>>>>>> function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<< > [ 0.341119] -0 0dp.1 48004us : sched_init <-start_kernel > [ 0.341520] -0 0dp.1 48005us : wait_bit_init <-sched_init > [ 0.341926] -0 0dp.1 48007us : hrtimer_init > <-init_rt_bandwidth > [ 0.342359] -0 0dp.1 48007us : __hrtimer_init <-hrtimer_init > [ 0.342779] -0 0dp.1 48007us : cpudl_init <-init_rootdomain > [ 0.343196] -0 0dp.1 48008us : cpupri_init <-init_rootdomain > [ 0.343618] -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] -0 0dp.. 154207us : boot_cpu_init <-start_kernel > ... > [ 0.333397] -0 0dp.. 180362us : mem_init <-start_kernel > [ 0.333806] -0 0dp.. 180365us : gart_iommu_hole_init > <-pci_iommu_alloc > [ 0.334330] -0 0dp.. 180652us : kmem_cache_init > <-start_kernel > [ 0.334760] -0 0dp.. 180810us : vmalloc_init <-start_kernel > >>>>>>>>>>>>>>>> function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<< > [ 0.335225] -0 0dp.1 180810us : sched_init <-start_kernel > [ 0.335626] -0 0dp.1 180810us : wait_bit_init <-sched_init > [ 0.336015] -0 0dp.1 180810us : hrtimer_init > <-init_rt_bandwidth > [ 0.336500] -0 0dp.1 180810us : __hrtimer_init <-hrtimer_init > [ 0.336981] -0 0dp.1 180810us : cpudl_init <-init_rootdomain > [ 0.337381] -0 0dp.1 180810us : cpupri_init <-init_rootdomain >