From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-wm1-f44.google.com (mail-wm1-f44.google.com [209.85.128.44]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 4A670328B54 for ; Wed, 26 Nov 2025 12:55:37 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.128.44 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1764161740; cv=none; b=hKAF7HaoqulfE93bw2YX1B6bkKgu23lkyz9AFfIBSQ0MFqMkOoLficpqOOAJ/ENokgf5ImuZVVdWzruzcgB8rZ/sSww4a1gdKjhLrBbPF6YxKCNUg/Xavu/oVHaWru97ks13iY1mL05ygAR7+gf6Fz1ksdjEUQD23WqKG9LPCVA= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1764161740; c=relaxed/simple; bh=uED5a7iSGpxFtHihi2C4Q+xB6s/168K7zdZ5PY0KqUE=; h=Date:From:To:Cc:Subject:Message-ID:References:MIME-Version: Content-Type:Content-Disposition:In-Reply-To; b=n9+3y1/i5RKpsZkchvppvTtLxxHex4esVQFkQIDiqmBvx6rfdHUMRhyc0nM0NGhIL6PbkMQFb1Y77pFeWjnl/f6Bb0sadzY02zWl0eYioKK208lGngy6qVSsDlBI9phcAlunJmk4N+Vzf5D2ALX23el130CqPgCUj7fq2YUekjM= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com; spf=pass smtp.mailfrom=suse.com; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b=JAf8dNP9; arc=none smtp.client-ip=209.85.128.44 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=suse.com Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b="JAf8dNP9" Received: by mail-wm1-f44.google.com with SMTP id 5b1f17b1804b1-477b91680f8so52513695e9.0 for ; Wed, 26 Nov 2025 04:55:36 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=google; t=1764161735; x=1764766535; darn=vger.kernel.org; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:from:to:cc:subject:date:message-id:reply-to; bh=c2vJlIMpTVo0GsxLS9m/HKFB95uCVQEqWI88dTXzXL0=; b=JAf8dNP9VoB95JQFmk5TFqCva3zhpkVJj48N7Q1DocpJwoWx2F1PnhANMMUujfsYvb ElfsK9iEkcjg8SDzMSJQ//cZnPnzTLDjlgWPrfWQ2RWFraNlWRlmq3tDodgXSS256Fig OztAUVl+q1nGuqY3XlX0Dn9oRJ4GmsxL29vveXwJCjFXF6UFTw/ABm1nwn3T+9OgGu0c islwE4YkYGL0FX/WeZPt8BOEe3ZW75nPEifkiiDcbrBn6qgXB8+YJUzgW+EyEGcbi39y ifE+REadLpeINPob6gDcj3o8Fa1w6/tQQclgN6/8mUIam7UIwqnhwzaXJ5Wi7yRGXqkK YoGg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1764161735; x=1764766535; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:x-gm-gg:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=c2vJlIMpTVo0GsxLS9m/HKFB95uCVQEqWI88dTXzXL0=; b=Bw33mpTUekdcHF5vYuOYqTPWFO2dLqVgzggPTtWGJi15uBK6/kP+ovp5w3zpE485lv 2yww43kk2dKOSJN3POOo+UrfdP/iUOhpDb5C9xdomHpA/WjVJqtnAWLRS4l2IjbrJCbZ gzS0V3KOqdD0W8ijnhtB3o71iubcYPYwXmxBQDrNOUOif4VZbajt3vKM2csKrqwYNK7z 2FKTe4WcC4kNjFpFcNO8awo17/ZplWZXg1mlCKeahIRy914G7rsvOTwIW7bbgOlY1I+0 YFRiwc0tR1TwyA7Csvg93NpSLLL7RA3nv0QIY5rvAnGx6PaZ45FBpODyTve+02aIc841 Zq8A== X-Forwarded-Encrypted: i=1; AJvYcCXoWjcJ4ESRt9pG2KUjYxgbCDJOnRq8y37c+wAjLhG5Al2oxVcNYsxWVD7d4aunupqfuqFqIwmnzVWMO2M=@vger.kernel.org X-Gm-Message-State: AOJu0YwzhnhNaEBljNhCPaQWS/CYll9WwYLVqtycYq4kzyHboTRj90kN Y/WZUyIoQTLQpvLpksAydBb8Vm1hyCRF46a/PNtFdRiDPxJCAdPKvm5tcXxGN7l2uOY= X-Gm-Gg: ASbGncv5XkUA/wr4HvJUWkNNEGWiuWX7ZcMFY3JPJo4jUktBKhcAStWsRV/xqxE6U1X 3l+CPPD+zw5mVEk/GLZzq+HvaHXqLL7SBYldyLmdDyuoMGy8+iLOsrNkyOKerfVMm4XCtzEjF00 YKvQjZdcRuuZIqa3JWBDPqFXRiLbr/qgO2757sUm3bPdzpIAus58+gRY1FVhW4N0VHAT8R9ng6w LdvqjFK0d36G4k2p3or0JfCJSbWot1MirIny6QzXQEY/exXLL8m4zEpA2sZs14PtYtaCInWpyS9 MRoF4OiPX77xuDCNJ8tFsjlAD53XjsJkz7AxthoQ4uzuOg9or/gPdgGXSDpuvz/TYh0JtT3bpab AV1J/4BQW72eXOsMXPK3znVjpJxNZmKZtiI3M/63zPeT6lbo6estSY1F1jmMPezG6qcfkOvn7mu Ql/m5vyAh+CjS4XQ== X-Google-Smtp-Source: AGHT+IEeoDSLJrpNt/pDvT31OuLPP8pn7uR1w1BMXtakeH3e5ah7DcmOaz5yt4hY1rLc42un9qLyNw== X-Received: by 2002:a05:600c:19cd:b0:477:c37:2ea7 with SMTP id 5b1f17b1804b1-477c1115febmr145030035e9.21.1764161735390; Wed, 26 Nov 2025 04:55:35 -0800 (PST) Received: from pathway.suse.cz ([176.114.240.130]) by smtp.gmail.com with ESMTPSA id ffacd0b85a97d-42cb7fd8e54sm41499132f8f.40.2025.11.26.04.55.34 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 26 Nov 2025 04:55:34 -0800 (PST) Date: Wed, 26 Nov 2025 13:55:32 +0100 From: Petr Mladek To: Francesco Valla Cc: Tim Bird , Steve Rostedt , john.ogness@linutronix.de, senozhatsky@chromium.org, Tim Bird , Andrew Morton , LKML , Anna-Maria Behnsen , Frederic Weisbecker , Thomas Gleixner , Linux Embedded Subject: Re: [PATCH] printk: add early_counter_ns routine for printk blind spot Message-ID: References: <39b09edb-8998-4ebd-a564-7d594434a981@bird.org> Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: On Tue 2025-11-25 14:08:40, Francesco Valla wrote: > Hi Tim, > > I tested this on my i.MX93 FRDM (arm64) board and after a bit of > fiddling with the MULT/SHIFT values I got it working. It can be a very > valuable addition. > > Some comments follow. > > On Mon, Nov 24, 2025 at 10:30:52PM -0700, Tim Bird wrote: > > From: Tim Bird > > > > During early boot, printk timestamps are reported as zero, > > which creates a blind spot in early boot timings. This blind > > spot hinders timing and optimization efforts for code that > > executes before time_init(), which is when local_clock() is > > initialized sufficiently to start returning non-zero timestamps. > > This period is about 400 milliseconds for many current desktop > > and embedded machines running Linux. > > > > Add an early_counter_ns function that returns nanosecond > > timestamps based on get_cycles(). get_cycles() is operational > > on arm64 and x86_64 from kernel start. Add some calibration > > printks to allow setting configuration variables that are used > > to convert cycle counts to nanoseconds (which are then used > > in early printks). Add CONFIG_EARLY_COUNTER_NS, as well as > > some associated conversion variables, as new kernel config > > variables. > > > > After proper configuration, this yields non-zero timestamps for > > printks from the very start of kernel execution. The timestamps > > are relative to the start of the architecture-specific counter > > used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64). > > This means that the time reported reflects time-from-power-on for > > most embedded products. This is also a useful data point for > > boot-time optimization work. > > > > Note that there is a discontinuity in the timestamp sequencing > > when standard clocks are finally initialized in time_init(). > > The printk timestamps are thus not monotonically increasing > > through the entire boot. > > This is... not going to work, IMO, and might lead to breakages in > userspace tools (are printk timings a userspace API?). Honestly, I am not sure if it would break anything. The fact is that printk() always used monotonic timers. And it is possible that some userspace depends on it. I personally thing that non-monotonic time stamps might be confusing but they should not cause any serious breakage. But I might be wrong. People are creative... > I actually have a counter-proposal: the time obtained through cycle > evaluation is used as an offset to be added to the printk time after > time_init() is called. A (working, but maybe sub-optimal) patch to > obtain this is attached at the end. I am not sure if this is a good idea. The offset would cause that all post-timer-init printk timestamps differ from values provided by the timer API. And it might cause confusion, for example, when they are printed as part of the message, or when analyzing a crash dump. On the other hand, there are various clock sources in the kernel which are not comparable anyway. So maybe I am too cautious. > > --- a/init/Kconfig > > +++ b/init/Kconfig > > @@ -770,6 +770,53 @@ config IKHEADERS > > or similar programs. If you build the headers as a module, a module called > > kheaders.ko is built which can be loaded on-demand to get access to headers. > > > > +config EARLY_COUNTER_NS > > + bool "Use counter for early printk timestamps" > > + default y > > + depends on PRINTK > > + help > > + Use a cycle-counter to provide printk timestamps during early > > + boot. This allows seeing timing information that would > > + otherwise be displayed with 0-valued timestamps. > > + > > + In order for this to work, you need to specify values for > > + EARLY_COUNTER_MULT and EARLY_COUNTER_SHIFT, used to convert > > + from the cycle count to nanoseconds. > > + > > +config EARLY_COUNTER_MULT > > + int "Multiplier for early cycle counter" > > + depends on PRINTK && EARLY_COUNTER_NS > > + default 1 > > + help > > + This value specifies a multiplier to be used when converting > > + cycle counts to nanoseconds. The formula used is: > > + ns = (cycles * mult) >> shift > > + > > + Use a multiplier that will bring the value of (cycles * mult) > > + to near a power of two, that is greater than 1000. The > > + nanoseconds returned by this conversion are divided by 1000 > > + to be used as the printk timestamp counter (with resolution > > + of microseconds). > > + > > + As an example, for a cycle-counter with a frequency of 200 Mhz, > > + the multiplier would be: 10485760, and the shift would be 21. > > + > > If I got this correclty: > > EARLY_COUNTER_MULT = (10^9 / freq) << EARLY_COUNTER_SHIFT > > where EARLY_COUNTER_SHIFT can be chosen at will, provided it is big > enough to survice the ns->us conversion but small enough not to overflow > the u64 container. > > > +config EARLY_COUNTER_SHIFT > > + int "Shift value for early cycle counter" > > + range 0 63 > > + depends on PRINTK && EARLY_COUNTER_NS > > + default 0 > > + help > > + This value specifies a shift value to be used when converting > > + cycle counts to nanoseconds. The formula used is: > > + ns = (cycles * mult) >> shift > > + > > + Use a shift that will bring the result to a value > > + in nanoseconds. > > + > > + As an example, for a cycle-counter with a frequency of 200 Mhz, > > + the multiplier would be: 10485760, and the shift would be 21. > > + > > config LOG_BUF_SHIFT > > int "Kernel log buffer size (16 => 64KB, 17 => 128KB)" > > range 12 25 So, it is usable only for a particular HW. It is not usable for a generic kernel which is supposed to run on misc HW. I guess that there is no way to detect the CPU frequency at runtime? Best Regards, Petr