Skip to contentSkip to conversation

kmsg01: set/restore console log level

PATCH New Jan Stancek 2 participants 6 messages Oct 23, 2017 – Oct 26, 2017

lore
Share & tools
lore
#0 lore raw

PATCH 1/3 kmsg01: set/restore console log level

commit 497564c77836 "kmsg01: lower the volume of message going to console" lowered message priority for the flood of messages that try to overwrite whole buffer. This works only for default console_loglevel. If anything increases console_loglevel (for example a call to console_verbose() via lockdep) system starts flooding also console. This causes a failure on systems with slower serial console, because test is unable to complete in 5 minutes.

Before patch:
<timeout>

After patch:
real 0m9.219s
user 0m0.289s
sys 0m4.027s

---
 testcases/kernel/logging/kmsg/kmsg01.c | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)
testcases/kernel/logging/kmsg/kmsg01.c +19 -0
index 294d0a2d1495..393acdcc71c6 100644
@@ -52,7 +52,10 @@
 #define NUM_READ_RETRY 10
 #define NUM_OVERWRITE_MSGS 1024
 #define READ_TIMEOUT 5
+#define PRINTK "/proc/sys/kernel/printk"
+#define CONSOLE_LOGLEVEL_QUIET   4
 
+static int console_loglevel = -1;
 
 /*
  * inject_msg - write message to /dev/kmsg
@@ -571,7 +574,23 @@ static void test_kmsg(void)
 	test_seek();
 }
 
+static void setup(void)
+{
+	if (access(PRINTK, F_OK) == 0) {
+		SAFE_FILE_SCANF(PRINTK, "%d", &console_loglevel);
+		SAFE_FILE_PRINTF(PRINTK, "%d", CONSOLE_LOGLEVEL_QUIET);
+	}
+}
+
+static void cleanup(void)
+{
+	if (console_loglevel != -1)
+		SAFE_FILE_PRINTF(PRINTK, "%d", console_loglevel);
+}
+
 static struct tst_test test = {
+	.setup = setup,
+	.cleanup = cleanup,
 	.needs_root = 1,
 	.test_all = test_kmsg,
 	.min_kver = "3.5.0"
Signature · 1 line
1.8.3.1
#1 lore raw

PATCH 2/3 kmsg01: specify read timeout in usec

---
 testcases/kernel/logging/kmsg/kmsg01.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)
testcases/kernel/logging/kmsg/kmsg01.c +8 -8
index 393acdcc71c6..b81c077cbd23 100644
@@ -51,7 +51,7 @@
 #define NUM_READ_MSGS 3
 #define NUM_READ_RETRY 10
 #define NUM_OVERWRITE_MSGS 1024
-#define READ_TIMEOUT 5
+#define READ_TIMEOUT 5000000
 #define PRINTK "/proc/sys/kernel/printk"
 #define CONSOLE_LOGLEVEL_QUIET   4
 
@@ -148,14 +148,14 @@ static int get_msg_fields(const char *msg, unsigned long *prio,
 /*
  * timed_read - if possible reads from fd or times out
  * @fd:           fd to read from
- * @timeout_sec:  timeout in seconds
+ * @timeout_usec: timeout in useconds
  *
  * RETURNS:
  *   read bytes on successful read
  *  -1 on read() error, errno reflects read() errno
  *  -2 on timeout
  */
-static int timed_read(int fd, int timeout_sec)
+static int timed_read(int fd, long timeout_usec)
 {
 	int ret, tmp;
 	struct timeval timeout;
@@ -163,8 +163,8 @@ static int timed_read(int fd, int timeout_sec)
 
 	FD_ZERO(&read_fds);
 	FD_SET(fd, &read_fds);
-	timeout.tv_sec = timeout_sec;
-	timeout.tv_usec = 0;
+	timeout.tv_sec = timeout_usec / 1000000;
+	timeout.tv_usec = timeout_usec % 1000000;
 
 	ret = select(fd + 1, &read_fds, 0, 0, &timeout);
 	switch (ret) {
@@ -183,14 +183,14 @@ static int timed_read(int fd, int timeout_sec)
  *                   read fails or times out. This ignores any
  *                   EPIPE errors.
  * @fd:           fd to read from
- * @timeout_sec:  timeout in seconds for every read attempt
+ * @timeout_usec: timeout in useconds for every read attempt
  *
  * RETURNS:
  *     0 on read reaching eof
  *    -1 on read error, errno reflects read() errno
  *    -2 on timeout
  */
-static int timed_read_kmsg(int fd, int timeout_sec)
+static int timed_read_kmsg(int fd, long timeout_usec)
 {
 	int child, status, ret = 0;
 	int pipefd[2];
@@ -226,7 +226,7 @@ static int timed_read_kmsg(int fd, int timeout_sec)
 
 	/* parent reads pipe until it reaches eof or until read times out */
 	do {
-		TEST(timed_read(pipefd[0], timeout_sec));
+		TEST(timed_read(pipefd[0], timeout_usec));
 	} while (TEST_RETURN > 0);
 	SAFE_CLOSE(pipefd[0]);
 
Signature · 1 line
1.8.3.1
#2 lore raw

PATCH 3/3 kmsg01: use lower timeout for test_read_block()

In reply to Jan Stancek

Test is currently expecting that read will block for ~5 seconds. This is a problem for busy systems, where there are many messages periodically generated. One example is ie31200_edac module, which periodically generates a message every second on debug kernels.

---
 testcases/kernel/logging/kmsg/kmsg01.c | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)
testcases/kernel/logging/kmsg/kmsg01.c +2 -3
index b81c077cbd23..7f077c9a3f4c 100644
@@ -51,7 +51,6 @@
 #define NUM_READ_MSGS 3
 #define NUM_READ_RETRY 10
 #define NUM_OVERWRITE_MSGS 1024
-#define READ_TIMEOUT 5000000
 #define PRINTK "/proc/sys/kernel/printk"
 #define CONSOLE_LOGLEVEL_QUIET   4
 
@@ -252,7 +251,7 @@ static void test_read_nonblock(void)
 	tst_res(TINFO, "TEST: nonblock read");
 	fd = SAFE_OPEN("/dev/kmsg", O_RDONLY | O_NONBLOCK);
 
-	TEST(timed_read_kmsg(fd, READ_TIMEOUT));
+	TEST(timed_read_kmsg(fd, 5000000));
 	if (TEST_RETURN == -1 && TEST_ERRNO == EAGAIN)
 		tst_res(TPASS, "non-block read returned EAGAIN");
 	else
@@ -268,7 +267,7 @@ static void test_read_block(void)
 	tst_res(TINFO, "TEST: blocking read");
 	fd = SAFE_OPEN("/dev/kmsg", O_RDONLY);
 
-	TEST(timed_read_kmsg(fd, READ_TIMEOUT));
+	TEST(timed_read_kmsg(fd, 500000));
 	if (TEST_RETURN == -2)
 		tst_res(TPASS, "read blocked");
 	else
Signature · 1 line
1.8.3.1
#3 lore raw

PATCH 3/3 kmsg01: use lower timeout for test_read_block()

Hi!

Quoted 5 lines

Test is currently expecting that read will block for ~5 seconds. This is a problem for busy systems, where there are many messages periodically generated. One example is ie31200_edac module, which periodically generates a message every second on debug kernels.

Sounds reasonable to me. Consider the whole patchset acked.

Signature · 2 lines
Cyril Hrubis
[email protected]
#4 lore raw

PATCH 3/3 kmsg01: use lower timeout for test_read_block()

----- Original Message -----

Quoted 8 lines

Hi!

Quoted 5 lines

Test is currently expecting that read will block for ~5 seconds. This is a problem for busy systems, where there are many messages periodically generated. One example is ie31200_edac module, which periodically generates a message every second on debug kernels.

Sounds reasonable to me. Consider the whole patchset acked.

Pushed.

Regards,
Jan