From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-pl1-f178.google.com (mail-pl1-f178.google.com [209.85.214.178]) (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 F31F7A29 for ; Fri, 24 Jan 2025 04:34:55 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.214.178 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737693297; cv=none; b=dor7XQF/Vr987VVH/2hYr/wCChVIBJi6pnCZ6SlS41pvef1N2N+f11kWctcQIRKR45Tgs/ue/By12efAxh4c5c/qnm2GjXeMiqAD6I/bL0+YlHWRZcdq9n4ngpBqhRpJsGO4ObZPUqTaNNph4/OU7PR7cO4r5jsG3mg9fUzQj2s= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737693297; c=relaxed/simple; bh=8FaBvUgqbQmmeCdpU9ke4q2fKcOO5VVN3aWPrk4OxfQ=; h=From:To:Cc:References:In-Reply-To:Subject:Date:Message-ID: MIME-Version:Content-Type; b=aoWetJl69Np7kadL8Qu6f2B6xSaqQXhpEgrS8Isgnj2QrZaC146RXIZhRFc5QQoB4CEAHmCynWn0dtV13r3RmMvzIPnbR3hz3mDC1EMt2fjovGk+8Z9UNRbgDCnEgmr6LlXePfqDh42Y5L+yyHLmZp15pXUUEAI9bWo/sYU+3x8= 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=O4q4+DQK; arc=none smtp.client-ip=209.85.214.178 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="O4q4+DQK" Received: by mail-pl1-f178.google.com with SMTP id d9443c01a7336-21675fd60feso37604795ad.2 for ; Thu, 23 Jan 2025 20:34:55 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telus.net; s=google; t=1737693295; x=1738298095; darn=vger.kernel.org; h=thread-index:content-language: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=x6DHIAYG7mJLrtUUxRB+yr169yAzZYsfe2YhVqx3EVc=; b=O4q4+DQKtF7eb6W1o7vN34+9Vnn2higMkLFIBzuOFAu7HdfqvCEGNC0oA56vyhgwYH ylmziLjWF0acy2Ya1JNjKRbJvHt1nZTU/4QuC3+PS5el2op+CUTQY1Ih1R/jzaliu7BJ KFTwPWJmYSEhfNsLrgsP8+ZxqTSheo5RJurai6r3Sq500shl14A7d96ryywdN7Rb1Ara OWALON4lzhHI/jh6pys28sOj9Kcfn3woqxGZ6+xleErrT6e3sy2JOMh8wJgBRI07WaIP e87gtBQkpaJo90/lspf9Fm4ZA0zrXOB+6PBAkO8iRyQcaSTr8ojh2S7gpN60qb6PyDww E3cA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1737693295; x=1738298095; h=thread-index:content-language: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=x6DHIAYG7mJLrtUUxRB+yr169yAzZYsfe2YhVqx3EVc=; b=CyflNnWOOdNnPclFfb3YsC7lZlESXxD2OUt0ccamM8N0DZfgH3tvZQFjz7VG3Tw8/k bd0ZCMv2VNLIdGT3IBRtxvuMr7SNGqV3xDZFBTcEFb1dYB8UDpzgF7sIq58Zm/s2mcdp RgWIjGBUTOL+JXil+SDxO1j0Vc8oqVoeJ3HLGj72sssozqF8hqjtf2Bo+yZ8ZwelT9xA S1zQYVZ34jTuPg/q5OjnPA2MPsPVbePXrga6xzvPA8Yv+n5KNxtL1enoLZSkK5O8Npe4 Sd+nI7/49wAWrJxWqtlVHEPxnzbs2Antx9A0ES2XYkcP+D4U9Le2Sx7Ci18ge6ZHsyvC PqPA== X-Gm-Message-State: AOJu0YxIQlMoCj3Cri9BmAG2ODMtNhf4LHeL3JDN79VYnw1rTzK6Ei7T 2oyANonsLKWxyxVn+5s7dpjhUgeT0VUVnQb2UJW/6L6omIvykSzWp1dWzD3sRno= X-Gm-Gg: ASbGncsiVk8jJJhvSs25yyWn8WRJBqdV7Ge5WFhTEb8VyrfUXSAmW5nl6llSDVy+hGE bndJgJCByCHPLMXPh4zAwrGSTZU6bjNdYRUD8ke/zHyoqzFZX3xmOFgw7UzqZpeOwu+vXeHE0tI hS70zv19ODqT4h+BL7YCyxN9p1stCMt5t5bbrz1GjiZ5OvX45fMhrGaP1dWAXoMA/YoBni+DIo4 851CdK5DF+XgjTza2Df33XRsm0PV5D///PvAtGRCt5UIcuWnloG1fo8cwg5yhTZkLWvAercriyH lTyMJMem1mSGQn//BMBNWikRDRJJ8H+QCTYfsF/A6kLy+kIyQvlOmB1Q X-Google-Smtp-Source: AGHT+IHUjj3O8rqadpQEj9KfZPyS2Ga5H1qO3l/R1M6uffyxUw5qDstFi0JvsY5Rng/NwA/rMMUeqw== X-Received: by 2002:a17:903:41c4:b0:216:4122:925f with SMTP id d9443c01a7336-21c3550ecb0mr430777965ad.14.1737693295169; Thu, 23 Jan 2025 20:34:55 -0800 (PST) Received: from DougS18 (s66-183-142-209.bc.hsia.telus.net. [66.183.142.209]) by smtp.gmail.com with ESMTPSA id d9443c01a7336-21da414df98sm6956675ad.190.2025.01.23.20.34.53 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Thu, 23 Jan 2025 20:34:53 -0800 (PST) From: "Doug Smythies" To: "'Peter Zijlstra'" Cc: , , "'Ingo Molnar'" , , "Doug Smythies" References: <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> <004901db6a06$59b12050$0d1360f0$@telus.net> <20250121084908.GD8603@noisy.programming.kicks-ass.net> <20250121112140.GJ8385@noisy.programming.kicks-ass.net> <001201db6c1d$4a0c19c0$de244d40$@telus.net> In-Reply-To: <001201db6c1d$4a0c19c0$de244d40$@telus.net> Subject: RE: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF Date: Thu, 23 Jan 2025 20:34:57 -0800 Message-ID: <00e301db6e19$52e3cc20$f8ab6460$@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 Content-Language: en-ca Thread-Index: AQGeOm19r/nCR0zGvNJA8J4AMG7PMAF6NJHoAFMZgMgCaxQKpgFP4l/5ASQn7WsCDo0DYQJ+LAk1ATBDaPIBYlAAxAKpEOBNAoASIX6zB6JnYA== On 2025.01.21 Doug Smythies wrote: > On 2025.01.21 03:22 Peter Zijlstra wrote: >> On Tue, Jan 21, 2025 at 09:49:08AM +0100, Peter Zijlstra wrote: >> >>>> I modified your tracing trigger thing in turbostat to this: >>> >>> Shiny! >>> >>> What turbostat invocation do I use? I think the last I had was: >>> >>> tools/power/x86/turbostat/turbostat --quiet --show Busy%,IRQ,Time_Of_Day_Seconds,CPU,usec --interval 1 >>> >>> I've started a new run of yes-vs-turbostate with the modified trigger >>> condition. Lets see what pops out. >> >> Ok, I have a trace.o >> >> So I see turbostat wake up on CPU 15, do its migration round 0-15 and >> when its back at 15 it prints the WHOOPSIE. >> >> (trimmed trace): >> >> yes-1169 [015] dNh4. 4238.261759: sched_wakeup: comm=turbostat pid=1185 prio=100 target_cpu=015 >> yes-1169 [015] d..2. 4238.261761: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R ==> > next_comm=turbostat next_pid=1185 next_prio=100 >> migration/15-158 [015] d..3. 4238.261977: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=15 dest_cpu=0 >> migration/0-20 [000] d..3. 4238.261991: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=0 dest_cpu=1 >> migration/1-116 [001] d..3. 4238.262003: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=1 dest_cpu=2 >> migration/2-25 [002] d..3. 4238.262018: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=2 dest_cpu=3 >> migration/3-122 [003] d..3. 4238.262031: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=3 dest_cpu=4 >> migration/4-31 [004] d..3. 4238.262044: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=4 dest_cpu=5 >> migration/5-128 [005] d..3. 4238.262057: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=5 dest_cpu=6 >> migration/6-37 [006] d..3. 4238.262071: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=6 dest_cpu=7 >> migration/7-134 [007] d..3. 4238.262084: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=7 dest_cpu=8 >> migration/8-43 [008] d..3. 4238.262097: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=8 dest_cpu=9 >> migration/9-140 [009] d..3. 4238.262109: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=9 dest_cpu=10 >> migration/10-49 [010] d..3. 4238.262123: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=10 dest_cpu=11 >> migration/11-146 [011] d..3. 4238.262136: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=11 dest_cpu=12 >> migration/12-55 [012] d..3. 4238.262150: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=12 dest_cpu=13 >> migration/13-152 [013] d..3. 4238.262164: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=13 dest_cpu=14 >> migration/14-62 [014] d..3. 4238.262177: sched_migrate_task: comm=turbostat pid=1185 prio=100 orig_cpu=14 dest_cpu=15 >> yes-1169 [015] d..2. 4238.262182: sched_switch: prev_comm=yes prev_pid=1169 prev_prio=120 prev_state=R+ ==> > next_comm=turbostat next_pid=1185 next_prio=100 >> turbostat-1185 [015] ..... 4238.262189: __x64_sys_gettimeofday: WHOOPSIE! >> >> The time between wakeup and whoopsie 4238.262189-4238.261759 = .000430 >> or 430us, which doesn't seem excessive to me. >> >> Let me go read this turbostat code to figure out what exactly the >> trigger condition signifies. Because I'm not seeing nothing weird here. > > I think the anomaly would have been about 1 second ago, on CPU 15, > and before entering sleep. > But after the previous call to the time of day stuff. > > Somewhere in this code: > > delta_platform(&platform_counters_even, &platform_counters_odd); > compute_average(ODD_COUNTERS); > format_all_counters(ODD_COUNTERS); > flush_output_stdout(); > > Please know that I ran a couple of tests yesterday for a total of about 8 hours > and never got a measured interval time >= 10 mSec. > I was using kernel 6.13, which includes your 2 patches, and I tried a slight > modification to the turbostat command: > > sudo ./turbostat --quiet --Summary --show Busy%,Bzy_MHz,IRQ,PkgWatt,PkgTmp,TSC_MHz,Time_Of_Day_Seconds,usec --interval 1 --out /dev/shm/turbo.log > > That allowed me to acquire more than my ssh session history limit of about 9000 lines (seconds) and also eliminated ssh > communications. > It was on purpose that I used RAM to write the log file to. I have run more tests over the last couple of days, totalling over 30 hours. I simply do not get a measured interval time >= 10mSec using kernel 6.13. The previous work was kernel 6.13-rc6 + the 2 patches + the tracing stuff. I never tried kernel 6.13-rc7.