From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-pl1-f171.google.com (mail-pl1-f171.google.com [209.85.214.171]) (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 0E3A21FA4 for ; Sun, 19 Jan 2025 00:09:02 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.214.171 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737245344; cv=none; b=SDFlO6FwQLnrUvQc0gBY3AcEU7YRYNhEyhS6DXoS4JGH+xOXdj18qJIHvlx7VF7MB4WKz0Z60WdJDLY+gfGzokzTiUdA3HJ5FsmMYxMoo86AoSHFR9KzPqEItZ48hpEiqo6auGNLriq+e5BYEm7mEVvyNk+XKdEUpdG4tCB0ZoE= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737245344; c=relaxed/simple; bh=Tp2OIj8kcT5rleDde2nDNJgA2yKeIY5KTUPn1bh4MRc=; h=From:To:Cc:References:In-Reply-To:Subject:Date:Message-ID: MIME-Version:Content-Type; b=d2yqKQ4JuQBWfFwHkehtBySL3yQkP4Oefm9K51vtBWiZgcLQQeaj865Fs8+lDZfq4wvf2/MhSzfm8UA5WXScGhr4ChuQScrdloamUs/FyAKHkqS5JBR6aMAubTypZX2buyleLLsQWEKhUtKI6mfqqMHz1hluLH2cJxFd6TW0x7c= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=telus.net; spf=pass smtp.mailfrom=telus.net; dkim=pass (2048-bit key) header.d=telus.net header.i=@telus.net header.b=HfDjloGS; arc=none smtp.client-ip=209.85.214.171 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=telus.net Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=telus.net Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=telus.net header.i=@telus.net header.b="HfDjloGS" Received: by mail-pl1-f171.google.com with SMTP id d9443c01a7336-21631789fcdso55076965ad.1 for ; Sat, 18 Jan 2025 16:09:02 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telus.net; s=google; t=1737245342; x=1737850142; darn=vger.kernel.org; h=content-language:thread-index:content-transfer-encoding :mime-version:message-id:date:subject:in-reply-to:references:cc:to :from:from:to:cc:subject:date:message-id:reply-to; bh=ehP7gpLwTMATTn+KDoIQ07djEc/xwy94DA1oBlkiF5U=; b=HfDjloGSkWh8PcigAVbuPLNrnz7qJKBzyYwEhK594onhciesCDwBHiHnqHwIqtATrd DunP4hLOVRAmQE1bZA8I2klU7lrPFr4n6yT17nQHkD6xYsuiUfT6Y3bqGjIdg8et3l2H Dt2MPleNuVyykz5DW4eh0gg2wmXsZxaEQe7u0NCkvjxvpqoAjcJE9LxO91nZbzZGimdn utY+tjxGcp6QLZgwUScxUN0HHGFvRUZ5bqYtgg3p1ww40pfIgjST9N0Y5zzZGCC65kys QcHUt/6scQRwI9TfNdYjy5pS+qo3s4+xRXz5EOgSc7dE5ahtC6Hik6U/QT6DlCuStfls ZaeQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1737245342; x=1737850142; h=content-language:thread-index:content-transfer-encoding :mime-version:message-id:date:subject:in-reply-to:references:cc:to :from:x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=ehP7gpLwTMATTn+KDoIQ07djEc/xwy94DA1oBlkiF5U=; b=ZPtSmoByAuWbqwQt9ZPn5vN83oz32Wk5ZjGzM+Ng7IF1mtkJaVMgBEyLYXxIN3n3ds 4brAT+q+6pMNEPPJ375/T5OtMqysj00TE+wnHEeb0bUq3SA5r/fI0SEDUIo9bY5EpJfn VT0+MJ7/ENxgUClNHYrC8hyyPTsqbmCqOPRRionJWGkJJmjH7eNJr8OXvPub5pHU+sZj e89P7HvZFTYLeuWoYR5nLC52pbXhw6qHPtSwTmNJBgk08bYri2lVwJZXvFv/PipB20On sBKafXA+s0qRrWLQXrMd5qvqaSFtAS13ZNKFvzEAim7aRhqdfbjSO1BPwyWDeza81HJU Y/4A== X-Gm-Message-State: AOJu0Yycq1+OwLdHthd+id+sQFfTopsz64ba12wgsD0UzTojb4HL9wW6 yfFFnE8m4iAN6Y6GID4wUZO6URAy37KoD/XGiaPs381Cj9MMtkk/QyiQm7mGXVM= X-Gm-Gg: ASbGncuglbEavuDOq/Gld3MzDPnF+I/N6Xu78kdZdsgSbwlSVerc7l3IYlEe3ehtOyy v7LhDFAwdnaKWoaQaMpz21Xcpu6tdrobiETqWoSW0kcjIKQwGCg1Jn7h8MArjZsvNJ9PaoXfWCq 8/OokoVy1FXm0N9pvqA2pSCVoZOjpiGb7GKy2bvupMKWDoW6Sr5dBAqvvaQyXb/2dcsG9vn5sSs pZGTe1/+KM8xq/+UkZL5FuUWzrFiEX0QvGvJP2JuxEHdWhSycjkmRaYNK0UUqT8D2f/kU4MIsSh 5yDRXZA6IF88lbxg751dEB9oqj8O8ACqLr4= X-Google-Smtp-Source: AGHT+IEFX6th4cgJONb9zWaGpwSgrPf1K4GKDRHdSMPLe67rOWilIa/KW8imlE5qVtQlMUgaYswpEA== X-Received: by 2002:a17:902:d4ca:b0:216:6ef9:60d with SMTP id d9443c01a7336-21bf0d07c06mr261604615ad.23.1737245342195; Sat, 18 Jan 2025 16:09:02 -0800 (PST) Received: from DougS18 (s66-183-142-209.bc.hsia.telus.net. [66.183.142.209]) by smtp.gmail.com with ESMTPSA id 41be03b00d2f7-a9bcc3224bcsm4104473a12.31.2025.01.18.16.08.59 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Sat, 18 Jan 2025 16:09:00 -0800 (PST) From: "Doug Smythies" To: "'Peter Zijlstra'" Cc: , , "'Ingo Molnar'" , , "Doug Smythies" References: <20250107112606.GN20870@noisy.programming.kicks-ass.net> <20250107192340.GB36003@noisy.programming.kicks-ass.net> <001501db618c$67bd8170$37388450$@telus.net> <20250108131205.GO20870@noisy.programming.kicks-ass.net> <001b01db61e4$c3ce5a40$4b6b0ec0$@telus.net> <20250109105959.GA2981@noisy.programming.kicks-ass.net> <002f01db631d$d265a600$7730f200$@telus.net> <20250110115720.GA17405@noisy.programming.kicks-ass.net> <00c201db6547$b43b9a50$1cb2cef0$@telus.net> <20250113110312.GD5388@noisy.programming.kicks-ass.net> <20250114105847.GC8385@noisy.programming.kicks-ass.net> In-Reply-To: <20250114105847.GC8385@noisy.programming.kicks-ass.net> Subject: RE: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF Date: Sat, 18 Jan 2025 16:09:02 -0800 Message-ID: <004901db6a06$59b12050$0d1360f0$@telus.net> 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-Transfer-Encoding: 7bit X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQFlSYB1PWVBqj20pPXP7hZ0SBLYDgHtSwJ2AyWxwjwBnjptfQF6NJHoAFMZgMgCaxQKpgFP4l/5ASQn7WsCDo0DYQJ+LAk1s3n0kCA= Content-Language: en-ca Hi Peter, An update. On 2025.01.14 02:59 Peter Zijlstra wrote: > On Mon, Jan 13, 2025 at 12:03:12PM +0100, Peter Zijlstra wrote: >> On Sun, Jan 12, 2025 at 03:14:17PM -0800, Doug Smythies wrote: >>> means that there were 19 occurrences of turbostat interval times >>> between 1.016 and 1.016999 seconds. >> >> OK, let me lower my threshold to 10ms and change the turbostat >> invocation -- see if I can catch me some wabbits :-) > > I've had it run overnight and have not caught a single >10ms event :-( Okay, so both you and I have many many hours of testing and never see >= 10ms in that area of the turbostat code anymore. The lingering >= 10ms (but I have never seen more than 25 ms) is outside of that timing. As previously reported, I thought it might be in the sampling interval sleep step, but I did a bunch of testing and it doesn't appear to be there. That leaves: delta_platform(&platform_counters_even, &platform_counters_odd); compute_average(ODD_COUNTERS); format_all_counters(ODD_COUNTERS); flush_output_stdout(); I modified your tracing trigger thing in turbostat to this: doug@s19:~/kernel/linux/tools/power/x86/turbostat$ git diff turbostat.c diff --git a/tools/power/x86/turbostat/turbostat.c b/tools/power/x86/turbostat/turbostat.c index 58a487c225a7..777efb64a754 100644 --- a/tools/power/x86/turbostat/turbostat.c +++ b/tools/power/x86/turbostat/turbostat.c @@ -67,6 +67,7 @@ #include #include #include +#include #define UNUSED(x) (void)(x) @@ -2704,7 +2705,7 @@ int format_counters(struct thread_data *t, struct core_data *c, struct pkg_data struct timeval tv; timersub(&t->tv_end, &t->tv_begin, &tv); - outp += sprintf(outp, "%5ld\t", tv.tv_sec * 1000000 + tv.tv_usec); + outp += sprintf(outp, "%7ld\t", tv.tv_sec * 1000000 + tv.tv_usec); } /* Time_Of_Day_Seconds: on each row, print sec.usec last timestamp taken */ @@ -2713,6 +2714,11 @@ int format_counters(struct thread_data *t, struct core_data *c, struct pkg_data interval_float = t->tv_delta.tv_sec + t->tv_delta.tv_usec / 1000000.0; + double requested_interval = (double) interval_tv.tv_sec + (double) interval_tv.tv_usec / 1000000.0; + + if(interval_float >= (requested_interval + 0.01)) /* was the last interval over by more than 10 mSec? */ + syscall(__NR_gettimeofday, &tv_delta, (void*)1); + tsc = t->tsc * tsc_tweak; /* topo columns, print blanks on 1st (average) line */ @@ -4570,12 +4576,14 @@ int get_counters(struct thread_data *t, struct core_data *c, struct pkg_data *p) int i; int status; + gettimeofday(&t->tv_begin, (struct timezone *)NULL); /* doug test */ + if (cpu_migrate(cpu)) { fprintf(outf, "%s: Could not migrate to CPU %d\n", __func__, cpu); return -1; } - gettimeofday(&t->tv_begin, (struct timezone *)NULL); +// gettimeofday(&t->tv_begin, (struct timezone *)NULL); if (first_counter_read) get_apic_id(t); And so that I could prove a correlation with the trace times and to my graph times I also did not turn off tracing upon a hit: doug@s19:~/kernel/linux$ git diff kernel/time/time.c diff --git a/kernel/time/time.c b/kernel/time/time.c index 1b69caa87480..fb84915159cc 100644 --- a/kernel/time/time.c +++ b/kernel/time/time.c @@ -149,6 +149,12 @@ SYSCALL_DEFINE2(gettimeofday, struct __kernel_old_timeval __user *, tv, return -EFAULT; } if (unlikely(tz != NULL)) { + if (tz == (void*)1) { + trace_printk("WHOOPSIE!\n"); +// tracing_off(); + return 0; + } + if (copy_to_user(tz, &sys_tz, sizeof(sys_tz))) return -EFAULT; } I ran a test for about 1 hour and 28 minutes. The data in the trace correlates with turbostat line by line TOD differentials. Trace got: turbostat-1370 [011] ..... 751.738151: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 760.763184: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1362.788298: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1365.815332: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1366.836340: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1367.856355: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1368.867365: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1373.893423: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1374.910439: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1377.928469: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1378.941483: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1379.959490: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1382.982525: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1385.005548: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1386.019561: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1387.030572: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1398.097683: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1620.752963: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1621.772969: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1622.788972: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1697.022098: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1703.071104: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1704.088103: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1705.105107: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1706.116106: __x64_sys_gettimeofday: WHOOPSIE! turbostat-1370 [011] ..... 1707.126107: __x64_sys_gettimeofday: WHOOPSIE! Going back to some old test data from when the CPU migration in turbostat often took up to 6 seconds. If I subtract that migration time from the measured interval time, I get a lot of samples between 10 and 23 ms. I am saying there were 2 different issues. The 2nd was hidden by the 1st because its magnitude was about 260 times less. I do not know if my trace is any use. I'll compress it and send it to you only, off list. My trace is as per this older email: https://lore.kernel.org/all/20240727105030.226163742@infradead.org/T/#m453062b267551ff4786d33a2eb5f326f92241e96