From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-pl1-f170.google.com (mail-pl1-f170.google.com [209.85.214.170]) (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 82AC81F1505 for ; Tue, 21 Jan 2025 15:58:18 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.214.170 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737475101; cv=none; b=YR6FGE+oWm6TeahwqXCvXSZbK4fpAnIbIfAfWnhopVgjcEmyGFWUCUFP2hsMCSGT0bALGLVKJzHfekdXNMmTySWVCxZ0ooUMlw9/VQ9C8M5dSw5ctzj6N1HaDAGNTuE6XdD4mXnxbLTeHo4ZYIprZUt/picXmcsFbxA9iZ2+6TU= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737475101; c=relaxed/simple; bh=0mDcCtpQV4mVELvLsKZqIBHRbu9UqlabKEXKFyLK6GI=; h=From:To:Cc:References:In-Reply-To:Subject:Date:Message-ID: MIME-Version:Content-Type; b=iOTIu7T3xAFyBZ6Lo1qYm4PzKu0dRrJDp4fn84ee/Oy9toNaWTMKf5ITQVED6bhwi2+N+0SmurYbcR3m4oqL4WKZFRcPQZLsoGduEeSKv/glcGE5j9VxAS6xvSnelAHGC/mWUR3IGeEoIAGloEm87sQ47BbP6B4m3Zdh86ZwxBY= 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=LLEwRXaJ; arc=none smtp.client-ip=209.85.214.170 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="LLEwRXaJ" Received: by mail-pl1-f170.google.com with SMTP id d9443c01a7336-21619108a6bso100807025ad.3 for ; Tue, 21 Jan 2025 07:58:18 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telus.net; s=google; t=1737475098; x=1738079898; 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=OS3DFzkp0iZimrcjlbqxvy66FeErV1NDGPq2tcO1+S8=; b=LLEwRXaJhBqlE/hGmYZqSnyaJxzwHH1vbnSGcJoaiOgeTppaoB+I8NI3mqfbvbJsI6 qJOER5HB01Lms4JDWPPcmifjKUvZpZn/flIt4sryuLP+nMAiCRNb4UZ8aNraU+QL/u9K Kjf6Fry2rfaaqQhqvdkjT00WMBdCD/hVPlR/z5LxQOHIEtVyDcqKppnXIXlhucDXSHi5 a3aY+Chq7VYMrBTeEgOGeOZRy4NW304aDLryEvCex86U9TX46hWz+TeMj262r6x6YLYM iVP56K8aCYbJRhhZgnVPooKvFo3oJ77tprvhWCFMFgBhhVWHCiqdtWCAFh0xtdYw/BpB 1AzQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1737475098; x=1738079898; 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=OS3DFzkp0iZimrcjlbqxvy66FeErV1NDGPq2tcO1+S8=; b=Xf4yWNGo/I52qKMYMGbf1VoCXndRsF7D576FJnb+pItbBuN458PgwfQDDCGsaLzUXG S2qwBDL5O0vrFCIPRFL0CGKpHoUgYRYdYm9uis38pAA3XIefp29wxgLN27VvTXy60Dmo RQwD/XtAmuUjyjX2nhtJW6bfkNLaIP8SPh0934YxkrtvYZkNmm8JBI+kZCK6trH5Azvw nDc3NP6XNmD8QVkceryg+fUkrjYomqnaKV6Qvad10YBemX53IyS+o/DSOvgMG1XzKNR8 Mqgj52AGjBUG5SXH0PZEmgLPFWbEVv9OZlE7F0t+K6JX09UZz0UiULXmglzCihu+6nOH K7Xw== X-Gm-Message-State: AOJu0YzsmRjSJs3JRW3nTQKfvAqCzzvl47tHSHQ/jO56RTKZZvgnICMV mQPj/IHNQ/co0nvnMIytc8zPksQOgPG5FBJ4KpMAS7Bcs1Iy9ovXffd7zUl5YxQ= X-Gm-Gg: ASbGncuLe+aINH0npDRVcvmbv5OL8FLolUkq5c7SilfTxhg2fec/FMg96b/3ZTuoZSa l6v7ZWlSVbSqNY8K4eNZeVoERw/Sa1eJ9c/8Xf0qgfT4p6OjCNpAtoDt++4XKP7osIVrsm5mes+ znF5iUux3yKtxkJ/Rk7tf6uHkP7SariftmiNrF5uA89znEHxCAh2Eq0g+erTlNBwwcbJQ4hJffA am50xsqG44gck0A3yqrRUIak9votyNXhRkSsS0FJTuegoz3rQDYVKV7LvyH8fYjJuBxK5j+A4Hf AZPcvxb9Q11dB9sYzH11faGUc5rZNS81xyDu+k5lq9VCPQ== X-Google-Smtp-Source: AGHT+IHwPV1c0/Dw29wGGi8hLzwkJO9zC/NC9sTAR820LYMUcJmFY2cJo3UyfvmdBGilevsjIESmRw== X-Received: by 2002:a17:903:2291:b0:216:2dc5:2330 with SMTP id d9443c01a7336-21c355b9335mr271842965ad.36.1737475097697; Tue, 21 Jan 2025 07:58:17 -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-21c2cea08e4sm79866415ad.7.2025.01.21.07.58.16 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Tue, 21 Jan 2025 07:58:16 -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> In-Reply-To: <20250121112140.GJ8385@noisy.programming.kicks-ass.net> Subject: RE: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF Date: Tue, 21 Jan 2025 07:58:18 -0800 Message-ID: <001201db6c1d$4a0c19c0$de244d40$@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: AQGeOm19r/nCR0zGvNJA8J4AMG7PMAF6NJHoAFMZgMgCaxQKpgFP4l/5ASQn7WsCDo0DYQJ+LAk1ATBDaPIBYlAAxAKpEOBNsxgX9MA= Content-Language: en-ca 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.