From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from desiato.infradead.org (desiato.infradead.org [90.155.92.199]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 218C81F151A for ; Tue, 21 Jan 2025 11:21:45 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=90.155.92.199 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737458507; cv=none; b=Sp5rY6xxUmE9OnJGK86fakFxnSYVXewUCfEbVqS6trkgmDbMNqFdjxARwYbdnnBco6DrNN64Dro6ZuHzWvEGK8iHnafFlvb+seN5XTMt+Kn3e+m2ofUoB3GjTZBPqKAfoGCDCuU1/X2piDVH3Jo1fRTnsngvw+exlFZ3sCxeLqk= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737458507; c=relaxed/simple; bh=CLngBkZYVI6sBSNkuXumLb+aj5NiSd+qZ+35lJbtpBY=; h=Date:From:To:Cc:Subject:Message-ID:References:MIME-Version: Content-Type:Content-Disposition:In-Reply-To; b=T/06LIXDY6Ga4zowVM7qdgkkp8Ks2JclBVcYvWfgdg4Fs/YJ9l7PcrZWmAS595KPjtXdqAodM78zT7K5hYfEh19h71hTV3wnbSXnTIppB68MdPK0DidGdRX6l/5FPO/T+weRkcMoMIYUKn9yY30goYs2qIOmKWJCD2MNySwLIA4= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=none (p=none dis=none) header.from=infradead.org; spf=none smtp.mailfrom=infradead.org; dkim=pass (2048-bit key) header.d=infradead.org header.i=@infradead.org header.b=TG0KWum3; arc=none smtp.client-ip=90.155.92.199 Authentication-Results: smtp.subspace.kernel.org; dmarc=none (p=none dis=none) header.from=infradead.org Authentication-Results: smtp.subspace.kernel.org; spf=none smtp.mailfrom=infradead.org Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=infradead.org header.i=@infradead.org header.b="TG0KWum3" DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=infradead.org; s=desiato.20200630; h=In-Reply-To:Content-Type:MIME-Version: References:Message-ID:Subject:Cc:To:From:Date:Sender:Reply-To: Content-Transfer-Encoding:Content-ID:Content-Description; bh=Ctm/6JXREZBoHMBn8uyeswkyW3ac8Hg1QbXicWAh410=; b=TG0KWum3iUJNSA1lmZtIjgPtHX ngLnhsQ9sqLPT14ZXx/B18CZP7nCqDbDFqeVO4Map9ElQ9coTu/sacmDiGN25nrZJSPQk8BC4kJYS e7ndAOub/0lpCqzElUgiH3drNQriE4tHkoqEPgMoHSu8H2h7PZ8oBG/cyj70b039xx5Tw9lIeFW1Z 8ox4Dl2zGJDdRQhUnmha5EGeyzx/oRZjUqlwIjezjqB5DRujeWsNo85O9M/ftcS0+nNpu/RnNl2fc uDE4zj985o8Ru0lebycto4U9v0o6qUlWD0MFi6l0EM+GASl1XwFpV5d0TcQ5Dn1GIsoWEHkmF1/hB S2rxxptg==; Received: from 77-249-17-89.cable.dynamic.v4.ziggo.nl ([77.249.17.89] helo=noisy.programming.kicks-ass.net) by desiato.infradead.org with esmtpsa (Exim 4.98 #2 (Red Hat Linux)) id 1taCKD-0000000DGO8-22Gc; Tue, 21 Jan 2025 11:21:41 +0000 Received: by noisy.programming.kicks-ass.net (Postfix, from userid 1000) id 63625300619; Tue, 21 Jan 2025 12:21:40 +0100 (CET) Date: Tue, 21 Jan 2025 12:21:40 +0100 From: Peter Zijlstra To: Doug Smythies Cc: linux-kernel@vger.kernel.org, vincent.guittot@linaro.org, 'Ingo Molnar' , wuyun.abel@bytedance.com Subject: Re: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF Message-ID: <20250121112140.GJ8385@noisy.programming.kicks-ass.net> 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> 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: <20250121084908.GD8603@noisy.programming.kicks-ass.net> 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.