| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20231107125434.284c44da@gandalf.local.home>
Date: Tue, 7 Nov 2023 12:54:34 -0500
From: Steven Rostedt <rostedt@...dmis.org>
To: Joel Fernandes <joel@...lfernandes.org>
Cc: Daniel Bristot de Oliveira <bristot@...nel.org>,
Ingo Molnar <mingo@...hat.com>,
Peter Zijlstra <peterz@...radead.org>,
Juri Lelli <juri.lelli@...hat.com>,
Vincent Guittot <vincent.guittot@...aro.org>,
Dietmar Eggemann <dietmar.eggemann@....com>,
Ben Segall <bsegall@...gle.com>, Mel Gorman <mgorman@...e.de>,
Daniel Bristot de Oliveira <bristot@...hat.com>,
Valentin Schneider <vschneid@...hat.com>,
linux-kernel@...r.kernel.org,
Luca Abeni <luca.abeni@...tannapisa.it>,
Tommaso Cucinotta <tommaso.cucinotta@...tannapisa.it>,
Thomas Gleixner <tglx@...utronix.de>,
Vineeth Pillai <vineeth@...byteword.org>,
Shuah Khan <skhan@...uxfoundation.org>,
Phil Auld <pauld@...hat.com>
Subject: Re: [PATCH v5 6/7] sched/deadline: Deferrable dl server
What's more interesting, when looking at the userspin task, I see a lot of this:
migrate-1153 [003] 1272.988097: sched_switch: migrate:1153 [90] S ==> userspin:1135 [120]
userspin-1135 [003] 1272.988111: sched_switch: userspin:1135 [120] R ==> migrate:1146 [97]
userspin sneaks in for 14 microseconds
migrate-1146 [003] 1272.988141: sched_switch: migrate:1146 [97] R ==> migrate:1159 [84]
migrate-1159 [003] 1272.988159: print: tracing_mark_write: thread 13 iter 15, took lock 15020 in 140726333419648 us
migrate-1159 [003] 1272.992161: print: tracing_mark_write: thread 13 iter 15, unlock lock 6
migrate-1159 [003] 1272.992169: print: tracing_mark_write: thread 13 iter 15 sleeping
migrate-1159 [003] 1272.992177: sched_switch: migrate:1159 [84] S ==> userspin:1135 [120]
userspin-1135 [003] 1272.992190: sched_switch: userspin:1135 [120] R ==> migrate:1150 [93]
Again for 13 microseconds.
migrate-1150 [003] 1272.995118: sched_switch: migrate:1150 [93] R ==> migrate:1153 [90]
migrate-1153 [003] 1272.995129: print: tracing_mark_write: thread 7 iter 15, taking lock 5
migrate-1153 [003] 1272.995164: print: tracing_mark_write: thread 7 iter 15, took lock 32 in 140726333419648 us
migrate-1153 [003] 1273.005166: print: tracing_mark_write: thread 7 iter 15, unlock lock 5
migrate-1153 [003] 1273.005174: print: tracing_mark_write: thread 7 iter 15 sleeping
migrate-1153 [003] 1273.005183: sched_switch: migrate:1153 [90] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.005204: sched_switch: userspin:1135 [120] R ==> migrate:1159 [84]
For 21 microseconds.
migrate-1159 [003] 1273.005216: print: tracing_mark_write: thread 13 iter 15, taking lock 7
migrate-1159 [003] 1273.005271: print: tracing_mark_write: thread 13 iter 15, took lock 53 in 140726333419648 us
migrate-1159 [003] 1273.009273: print: tracing_mark_write: thread 13 iter 15, unlock lock 7
migrate-1159 [003] 1273.009281: print: tracing_mark_write: thread 13 iter 15 sleeping
migrate-1159 [003] 1273.009289: sched_switch: migrate:1159 [84] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.009301: sched_switch: userspin:1135 [120] R ==> migrate:1147 [96]
12 microseconds
migrate-1147 [003] 1273.012205: sched_switch: migrate:1147 [96] R ==> migrate:1153 [90]
migrate-1153 [003] 1273.012217: print: tracing_mark_write: thread 7 iter 15, taking lock 6
migrate-1153 [003] 1273.012228: sched_switch: migrate:1153 [90] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.012242: sched_switch: userspin:1135 [120] R ==> migrate:1146 [97]
migrate-1146 [003] 1273.014251: sched_switch: migrate:1146 [97] R ==> migrate:1148 [95]
2 milliseconds. (which is probably fine).
migrate-1148 [003] 1273.020300: print: tracing_mark_write: thread 2 iter 14, unlock lock 2
migrate-1148 [003] 1273.020302: print: tracing_mark_write: thread 2 iter 14 sleeping
migrate-1148 [003] 1273.020309: sched_switch: migrate:1148 [95] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.020324: sched_switch: userspin:1135 [120] R ==> migrate:1147 [96]
15 microseconds.
migrate-1147 [003] 1273.020360: print: tracing_mark_write: thread 1 iter 14, unlock lock 1
migrate-1147 [003] 1273.020373: print: tracing_mark_write: thread 1 iter 14 sleeping
migrate-1147 [003] 1273.020381: sched_switch: migrate:1147 [96] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.021397: sched_switch: userspin:1135 [120] R ==> migrate:1147 [96]
1 millisecond.
migrate-1147 [003] 1273.021402: print: tracing_mark_write: thread 1 iter 14, taking lock 2
migrate-1147 [003] 1273.021404: print: tracing_mark_write: thread 1 iter 14, took lock 1 in 140726333419648 us
migrate-1147 [003] 1273.022200: sched_switch: migrate:1147 [96] R ==> migrate:1152 [91]
migrate-1152 [003] 1273.022206: print: tracing_mark_write: thread 6 iter 15, taking lock 6
migrate-1152 [003] 1273.022217: sched_switch: migrate:1152 [91] S ==> migrate:1147 [96]
migrate-1147 [003] 1273.022289: sched_switch: migrate:1147 [96] R ==> migrate:1159 [84]
migrate-1159 [003] 1273.022299: print: tracing_mark_write: thread 13 iter 16, taking lock 0
migrate-1159 [003] 1273.022326: print: tracing_mark_write: thread 13 iter 16, took lock 25 in 140726333419648 us
migrate-1159 [003] 1273.026328: print: tracing_mark_write: thread 13 iter 16, unlock lock 0
migrate-1159 [003] 1273.026337: print: tracing_mark_write: thread 13 iter 16 sleeping
migrate-1159 [003] 1273.026346: sched_switch: migrate:1159 [84] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.026359: sched_switch: userspin:1135 [120] R ==> migrate:1146 [97]
13 microseconds, and so on...
migrate-1146 [003] 1273.027170: sched_switch: migrate:1146 [97] R ==> migrate:1149 [94]
migrate-1149 [003] 1273.027189: print: tracing_mark_write: thread 3 iter 14, took lock 1927 in 140726333419648 us
migrate-1149 [003] 1273.027335: sched_switch: migrate:1149 [94] R ==> migrate:1153 [90]
migrate-1153 [003] 1273.027349: print: tracing_mark_write: thread 7 iter 15, took lock 15130 in 140726333419648 us
migrate-1153 [003] 1273.037352: print: tracing_mark_write: thread 7 iter 15, unlock lock 6
migrate-1153 [003] 1273.037362: print: tracing_mark_write: thread 7 iter 15 sleeping
migrate-1153 [003] 1273.037370: sched_switch: migrate:1153 [90] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.037395: sched_switch: userspin:1135 [120] R ==> migrate:1147 [96]
migrate-1147 [003] 1273.037406: print: tracing_mark_write: thread 1 iter 14, unlock lock 2
migrate-1147 [003] 1273.037408: print: tracing_mark_write: thread 1 iter 14 sleeping
migrate-1147 [003] 1273.037414: sched_switch: migrate:1147 [96] S ==> userspin:1135 [120]
userspin-1135 [003] 1273.038428: sched_switch: userspin:1135 [120] R ==> migrate:1147 [96]
It looks like it sneaks in when it's about to schedule a new RT task.
Is this expected?
-- Steve
Powered by blists - more mailing lists