From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-pj1-f52.google.com (mail-pj1-f52.google.com [209.85.216.52]) (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 E1C1D1F2389 for ; Tue, 7 Jan 2025 15:04:12 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.216.52 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736262254; cv=none; b=KtcUh3vQbZGKtgW9OUom9NzbSKvsLMortDh9MGfvaCt9HynoUbOzYkFVuD40M0WvCg/fZ9Xyz22g3JE9CKx8IhllJY+S9CibapGjdkMnVLrGxfYalFGocQ6lChxz3L13zZsn4c8rGu+Vc09Q+dYBgic66VtmG5AMlQWpX6aGh0M= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736262254; c=relaxed/simple; bh=eIVSVyumIOWo1VijMSIJN+ZqvPln49q8XoKWOXeAErU=; h=From:To:Cc:References:In-Reply-To:Subject:Date:Message-ID: MIME-Version:Content-Type; b=IGNijzIT3pz8xleZb8LiQwws0Lpnfegl9/aDm27CKyS0T5UUQqGfZc5K6ws4JOZ+plZib4fHvo+AnYfflgE7wC3fm4MK7KPgD7FRFVv8seQMYD4/jv2hfaImI4bgrlzklDI86DJ2mD99EkSdopHWXRsoGp68q8KYUBzy41nnVkk= 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=DcjAfD+c; arc=none smtp.client-ip=209.85.216.52 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="DcjAfD+c" Received: by mail-pj1-f52.google.com with SMTP id 98e67ed59e1d1-2ee51f8c47dso18122576a91.1 for ; Tue, 07 Jan 2025 07:04:12 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telus.net; s=google; t=1736262252; x=1736867052; 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=mDMjfiaPeWmF6Ld6TowOT8hPfiHKfumFBasE2dsWZ3E=; b=DcjAfD+c34N7glN9RLAoFIj1OOhVxxeOItD+jaHWMh0GnrrXaDpU3pnME7WgN1LUGi fgEtGhLrpEu2RsHTDR+tRTFOaeK/1k4vm2PxMA8TMAQWBudhP7aktzdO8Zp0tm96AFgn sv2octdO8+xT0GFKaVtV2noVLVJLCrtau1WpJU7d9Qqr28tuavDWsQ3RLWN2uLMgDopd xt9zPIeztXxvDUI4pFrpDgI3WD4QfsXTl8CnE7PZooFJnvJ27z0wHZQ0M8B/w0kTRota jv2XJxn6vvLplDWpJmOiwU8unxmnPChU4RKjabropE+x1KnS+sMyaR/+o9FgX9SIhVT5 OM/w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1736262252; x=1736867052; 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=mDMjfiaPeWmF6Ld6TowOT8hPfiHKfumFBasE2dsWZ3E=; b=OMdLM7cpTKUTEyRy2RhVZmnmbsRCmipXvxkMvYdZbZ3WDSFC88PkEmTJw0Kii869ZA SnYextFVclmq/QAduzXL/7jvp2PyK4XHhQoYsIDg3230OLpIRPd3/kHGwea5Yw6IVEPx ieS3cvfqFQk+yphHxAfEFsPRlSJmIPBHS0X0VmxVPVDO/J7XWxNpm2xvGBnPOXmggWWr CoWrO/XLnc/dO7WTu4GJpp80+l2VVKAs9k4/zpjYF5dxPrRTojF7UbdaFWh2ryHE7fzi g85oRjNRxoB5XBy6zpbb/taeZrIld9piSCg7ZzWqNoV1fOqu3wKswrMoxwukNTpmAJrQ vnYg== X-Gm-Message-State: AOJu0Yy27hkq6/0cRvluHh25Uw+wdMJ3JJzl/wBtpBY1/JILtVivpQsF XwJDJNywywGR5r58Hxr69BDUu4+5sZtU1i6URqZSAsTKkXA5dWVIvk+jl/OAFxY= X-Gm-Gg: ASbGncuqQfO/hV+3UoL4428+KDEpLCXT133AHnJDiSXTTu/J32SASE/YrIJX+aN28PD GksxUG3THdFsDS1amqYxGG6QfVoudopLz4a/q089EmR+p5GsFj3CWQzDQP1N3jiteEEeGqvmRVA XV6CErBokhWx4CyqS5M7l9EcKDN3hUkQbUOYmXQ939AYb8tNbQTJfgtQ03H4844iNmZB3l9pQAG U6WBD2EsiFCItzQMYcPb4+vIBp1VQWKPyGzL57IKX40H6o4RUTcBJkCy1XiZhlQaOCBMptZubof RHcdjeBd4LR8TtGBuGoDXg== X-Google-Smtp-Source: AGHT+IGWfM9F1xyCBE9pqDgCHxS7du0JjM1F6SuDvI0STkQXewtjIhgVyTokSjPyf6MRc/j0NkrrSg== X-Received: by 2002:a17:90b:54cb:b0:2ee:96a5:721e with SMTP id 98e67ed59e1d1-2f452e1cacamr118505433a91.12.1736262252059; Tue, 07 Jan 2025 07:04:12 -0800 (PST) Received: from DougS18 (s66-183-142-209.bc.hsia.telus.net. [66.183.142.209]) by smtp.gmail.com with ESMTPSA id 98e67ed59e1d1-2f4477c852csm35906636a91.22.2025.01.07.07.04.11 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Tue, 07 Jan 2025 07:04:11 -0800 (PST) From: "Doug Smythies" To: "'Peter Zijlstra'" Cc: , , "Doug Smythies" References: <005f01db5a44$3bb698e0$b323caa0$@telus.net> <20250106115732.GE20870@noisy.programming.kicks-ass.net> <000801db604b$e0f6b580$a2e42080$@telus.net> <20250106165932.GG20870@noisy.programming.kicks-ass.net> <20250106170455.GB22191@noisy.programming.kicks-ass.net> <001b01db608a$56d3dc40$047b94c0$@telus.net> <20250107112606.GN20870@noisy.programming.kicks-ass.net> In-Reply-To: <20250107112606.GN20870@noisy.programming.kicks-ass.net> Subject: RE: [REGRESSION] Re: [PATCH 00/24] Complete EEVDF Date: Tue, 7 Jan 2025 07:04:12 -0800 Message-ID: <000d01db6115$69c1aef0$3d450cd0$@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: AQJdvfVp9nqa9troPEySggPg+fzySgGTHC4vAVKdTGwBPBBbIAH1WJEKAgKs/R8BZUmAdbG6sGng On 2025.01.07 03:26 Peter Zijlstra wrote: > On Mon, Jan 06, 2025 at 02:28:40PM -0800, Doug Smythies wrote: > >> Which will show when a CPU migration took over 10 milliseconds. >> If you want to go further, for example to only display ones that took >> over a second and to include the target CPU, then patch turbostat: >> >> doug@s19:~/kernel/linux/tools/power/x86/turbostat$ git diff >> diff --git a/tools/power/x86/turbostat/turbostat.c b/tools/power/x86/turbostat/turbostat.c >> index 58a487c225a7..f8a73cc8fbfc 100644 >> --- a/tools/power/x86/turbostat/turbostat.c >> +++ b/tools/power/x86/turbostat/turbostat.c >> @@ -2704,7 +2704,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 */ >> @@ -4570,12 +4570,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); >> >> > > So I've taken the second node offline, running with 10 cores (20 > threads) now. > > usec Time_Of_Day_Seconds CPU Busy% IRQ > 106783 1736248404.951438 - 100.00 20119 > 46 1736248404.844701 0 100.00 1005 > 41 1736248404.844742 20 100.00 1007 > 42 1736248404.844784 1 100.00 1005 > 40 1736248404.844824 21 100.00 1006 > 41 1736248404.844865 2 100.00 1005 > 40 1736248404.844905 22 100.00 1006 > 41 1736248404.844946 3 100.00 1006 > 40 1736248404.844986 23 100.00 1005 > 41 1736248404.845027 4 100.00 1005 > 40 1736248404.845067 24 100.00 1006 > 41 1736248404.845108 5 100.00 1011 > 40 1736248404.845149 25 100.00 1005 > 41 1736248404.845190 6 100.00 1005 > 40 1736248404.845230 26 100.00 1005 > 42 1736248404.845272 7 100.00 1007 > 41 1736248404.845313 27 100.00 1005 > 41 1736248404.845355 8 100.00 1005 > 42 1736248404.845397 28 100.00 1006 > 46 1736248404.845443 9 100.00 1009 > 105995 1736248404.951438 29 100.00 1005 > > Is by far the worst I've had in the past few minutes playing with this. > > If I get a blimp (>10000) then it is always on the last CPU, are you > seeing the same thing? More or less, yes. The very long migrations are dominated by the CPU 5 to CPU 11 migration. Here is data from yesterday for other CPUs: usec Time_Of_Day_Seconds CPU Busy% IRQ 605706 1736224605.542844 0 99.76 1922 10001 1736224605.561844 1 99.76 1922 10999 1736224605.572843 7 99.76 1923 11001 1736224605.583844 2 99.76 1925 11000 1736224605.606844 4 99.76 1924 10999 1736224605.617843 10 99.76 1923 105001 1736224605.722844 5 99.76 1922 465657 1736224608.190843 8 99.76 1002 494000 1736224608.684843 3 99.76 1003 395674 1736224610.081843 7 99.76 1964 19679 1736224617.108843 7 99.76 1003 37709 1736224636.633845 0 99.76 1003 65641 1736224689.796843 9 99.76 1003 406631 1736224693.206843 4 99.76 1002 105622 1736225026.238843 10 99.76 1003 409622 1736225053.673843 10 99.76 1003 16706 1736225302.149847 0 99.76 1820 10000 1736225302.185846 4 99.76 1825 19663 1736225317.249844 7 99.76 1012 > >> In this short example all captures were for the CPU 5 to 11 migration. >> 2 at 6 seconds, 1 at 1.33 seconds and 1 at 2 seconds. > > This seems to suggest you are, always on CPU 11. > > Weird! Yes, weird. I think, but am not certain, the CPU sequence in turbostat per interval loop is: Wake on highest numbered CPU (11 in my case) Do a bunch of work that can be done without MSR reads. For each CPU in topological order (0,6,1,7,2,8,3,9,4,10,5,11 in my case) Do the CPU specific work Finish the intervals work and printing and such on CPU 11. Sleep for the interval time (we have been using 1 second) Without any proof, I was thinking the CPU 11 dominance for the long migration issue was due to the other bits of work done on that CPU. > Anyway, let me see if I can capture a trace of this..