s390/con3215: Drop console data printout when buffer full
authorThomas Richter <tmricht@linux.ibm.com>
Tue, 20 Sep 2022 12:26:16 +0000 (14:26 +0200)
committerVasily Gorbik <gor@linux.ibm.com>
Wed, 26 Oct 2022 12:46:51 +0000 (14:46 +0200)
Using z/VM the 3270 terminal emulator also emulates an IBM 3215 console
which outputs line by line. When the screen is full, the console enters
the MORE... state and waits for the operator to confirm the data
on the screen by pressing a clear key. If this does not happen in the
default time frame (currently 50 seconds) the console enters the HOLDING
state.
It then waits another time frame (currently 10 seconds) before the output
continues on the next screen. When the operator presses the clear key
during these wait times, the output continues immediately.

This may lead to a very long boot time when the console
has to print many messages, also the system may hang because of the
console's limited buffer space and the system waits for the console
output to drain and finally to finish. This problem can only occur
when a terminal emulator is actually connected to the 3215 console
driver. If not z/VM simply drops console output.

Remedy this rare situation and add a kernel boot command line parameter
con3215_drop. It can be set to 0 (do not drop) or 1 (do drop) which is
the default. This instructs the kernel drop console data when the
console buffer is full. This speeds up the boot time considerable and
also does not hang the system anymore.

Add a sysfs attribute file for console IBM 3215 named con_drop.
This allows for changing the behavior after the boot, for example when
during interactive debugging a panic/crash is expected.

Here is a test of the new behavior using the following test program:
 #/bin/bash
 declare -i cnt=4

 mode=$(cat /sys/bus/ccw/drivers/3215/con_drop)
 [ $mode = yes ] && cnt=25

 echo "cons_drop $(cat /sys/bus/ccw/drivers/3215/con_drop)"
 echo "vmcp term more 5 2"
 vmcp term more 5 2
 echo "Run $cnt iterations of "'echo t > /proc/sysrq-trigger'

 for i in $(seq $cnt)
 do
echo "$i. command 'echo t > /proc/sysrq-trigger' at $(date +%F,%T)"
echo t > /proc/sysrq-trigger
sleep 1
 done
 echo "droptest done" > /dev/kmsg
 #

Output with sysfs attribute con_drop set to 1:
 # ./droptest.sh
 cons_drop yes
 vmcp term more 5 2
 Run 25 iterations of echo t > /proc/sysrq-trigger
 1. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:09
 2. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:10
 3. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:11
 4. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:12
 5. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:13
 6. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:14
 7. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:15
 8. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:16
 9. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:17
 10. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:18
 11. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:19
 12. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:20
 13. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:21
 14. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:22
 15. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:23
 16. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:24
 17. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:25
 18. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:26
 19. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:27
 20. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:28
 21. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:29
 22. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:30
 23. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:31
 24. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:32
 25. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:15:33
 #

There are no hangs anymore.

Output with sysfs attribute con_drop set to 0 and identical
setting for z/VM console 'term more 5 2'. Sometimes hitting the
clear key at the x3270 console to progress output.

 # ./droptest.sh
 cons_drop no
 vmcp term more 5 2
 Run 4 iterations of echo t > /proc/sysrq-trigger
 1. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:20:58
 2. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:24:32
 3. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:28:04
 4. command 'echo t > /proc/sysrq-trigger' at 2022-09-02,10:31:37
 #

Details:
Enable function raw3215_write() to handle tab expansion and newlines
and feed it with input not larger than the console buffer of 65536
bytes. Function raw3125_putchar() just forwards its character for
output to raw3215_write().

This moves tab to blank conversion to one function raw3215_write()
which also does call raw3215_make_room() to wait for enough free
buffer space.

Function handle_write() loops over all its input and segments input
into chunks of console buffer size (should the input be larger).

Rework tab expansion handling logic to avoid code duplication.

Signed-off-by: Thomas Richter <tmricht@linux.ibm.com>
Acked-by: Peter Oberparleiter <oberpar@linux.ibm.com>
Acked-by: Heiko Carstens <hca@linux.ibm.com>
Signed-off-by: Vasily Gorbik <gor@linux.ibm.com>
Documentation/admin-guide/kernel-parameters.txt
drivers/s390/char/con3215.c

index a465d52..1c45b82 100644 (file)
        condev=         [HW,S390] console device
        conmode=
 
+       con3215_drop=   [S390] 3215 console drop mode.
+                       Format: y|n|Y|N|1|0
+                       When set to true, drop data on the 3215 console when
+                       the console buffer is full. In this case the
+                       operator using a 3270 terminal emulator (for example
+                       x3270) does not have to enter the clear key for the
+                       console output to advance and the kernel to continue.
+                       This leads to a much faster boot time when a 3270
+                       terminal emulator is active. If no 3270 terminal
+                       emulator is used, this parameter has no effect.
+
        console=        [KNL] Output console device and options.
 
                tty<n>  Use the virtual console device <n>.
index 03e2d3d..183d25a 100644 (file)
@@ -102,6 +102,7 @@ static struct raw3215_req *raw3215_freelist;
 static DEFINE_SPINLOCK(raw3215_freelist_lock);
 
 static struct tty_driver *tty3215_driver;
+static bool con3215_drop = true;
 
 /*
  * Get a request structure from the free list
@@ -446,14 +447,46 @@ put_tty:
        tty_kref_put(tty);
 }
 
+/*
+ * Need to drop data to avoid blocking. Drop as much data as possible.
+ * This is unqueued part in the buffer and the queued part in the request.
+ * Also adjust the head position to append new data and set count
+ * accordingly.
+ *
+ * Return number of bytes available in buffer.
+ */
+static unsigned int raw3215_drop(struct raw3215_info *raw)
+{
+       struct raw3215_req *req;
+
+       req = raw->queued_write;
+       if (req) {
+               /* Drop queued data and delete request */
+               raw->written -= req->len;
+               raw3215_free_req(req);
+               raw->queued_write = NULL;
+       }
+       raw->head = (raw->head - raw->count + raw->written) &
+                   (RAW3215_BUFFER_SIZE - 1);
+       raw->count = raw->written;
+
+       return RAW3215_BUFFER_SIZE - raw->count;
+}
+
 /*
  * Wait until length bytes are available int the output buffer.
+ * If drop mode is active and wait condition holds true, start dropping
+ * data.
  * Has to be called with the s390irq lock held. Can be called
  * disabled.
  */
-static void raw3215_make_room(struct raw3215_info *raw, unsigned int length)
+static unsigned int raw3215_make_room(struct raw3215_info *raw,
+                                     unsigned int length, bool drop)
 {
        while (RAW3215_BUFFER_SIZE - raw->count < length) {
+               if (drop)
+                       return raw3215_drop(raw);
+
                /* there might be a request pending */
                raw->flags |= RAW3215_FLUSHING;
                raw3215_mk_write_req(raw);
@@ -470,75 +503,89 @@ static void raw3215_make_room(struct raw3215_info *raw, unsigned int length)
                udelay(100);
                spin_lock(get_ccwdev_lock(raw->cdev));
        }
+       return length;
 }
 
+#define        RAW3215_COUNT   1
+#define        RAW3215_STORE   2
+
 /*
- * String write routine for 3215 devices
+ * Add text to console buffer. Find tabs in input and calculate size
+ * including tab replacement.
+ * This function operates in 2 different modes, depending on parameter
+ * opmode:
+ * RAW3215_COUNT: Get the size needed for the input string with
+ *     proper tab replacement calculation.
+ *     Return value is the number of bytes required to store the
+ *     input. However no data is actually stored.
+ *     The parameter todrop is not used.
+ * RAW3215_STORE: Add data to the console buffer. The parameter todrop is
+ *     valid and contains the number of bytes to be dropped from head of
+ *     string  without blocking.
+ *     Return value is the number of bytes copied.
  */
-static void raw3215_write(struct raw3215_info *raw, const char *str,
-                         unsigned int length)
+static unsigned int raw3215_addtext(const char *str, unsigned int length,
+                                   struct raw3215_info *raw, int opmode,
+                                   unsigned int todrop)
 {
-       unsigned long flags;
-       int c, count;
+       unsigned int c, ch, i, blanks, expanded_size = 0;
+       unsigned int column = raw->line_pos;
 
-       while (length > 0) {
-               spin_lock_irqsave(get_ccwdev_lock(raw->cdev), flags);
-               count = (length > RAW3215_BUFFER_SIZE) ?
-                                            RAW3215_BUFFER_SIZE : length;
-               length -= count;
-
-               raw3215_make_room(raw, count);
-
-               /* copy string to output buffer and convert it to EBCDIC */
-               while (1) {
-                       c = min_t(int, count,
-                                 min(RAW3215_BUFFER_SIZE - raw->count,
-                                     RAW3215_BUFFER_SIZE - raw->head));
-                       if (c <= 0)
-                               break;
-                       memcpy(raw->buffer + raw->head, str, c);
-                       ASCEBC(raw->buffer + raw->head, c);
-                       raw->head = (raw->head + c) & (RAW3215_BUFFER_SIZE - 1);
-                       raw->count += c;
-                       raw->line_pos += c;
-                       str += c;
-                       count -= c;
+       if (opmode == RAW3215_COUNT)
+               todrop = 0;
+
+       for (c = 0; c < length; ++c) {
+               blanks = 1;
+               ch = str[c];
+
+               switch (ch) {
+               case '\n':
+                       expanded_size++;
+                       column = 0;
+                       break;
+               case '\t':
+                       blanks = TAB_STOP_SIZE - (column % TAB_STOP_SIZE);
+                       column += blanks;
+                       expanded_size += blanks;
+                       ch = ' ';
+                       break;
+               default:
+                       expanded_size++;
+                       column++;
+                       break;
                }
-               if (!(raw->flags & RAW3215_WORKING)) {
-                       raw3215_mk_write_req(raw);
-                       /* start or queue request */
-                       raw3215_try_io(raw);
+
+               if (opmode == RAW3215_COUNT)
+                       continue;
+               if (todrop && expanded_size < todrop)   /* Drop head data */
+                       continue;
+               for (i = 0; i < blanks; i++) {
+                       raw->buffer[raw->head] = (char)_ascebc[(int)ch];
+                       raw->head = (raw->head + 1) & (RAW3215_BUFFER_SIZE - 1);
+                       raw->count++;
                }
-               spin_unlock_irqrestore(get_ccwdev_lock(raw->cdev), flags);
+               raw->line_pos = column;
        }
+       return expanded_size - todrop;
 }
 
 /*
- * Put character routine for 3215 devices
+ * String write routine for 3215 devices
  */
-static void raw3215_putchar(struct raw3215_info *raw, unsigned char ch)
+static void raw3215_write(struct raw3215_info *raw, const char *str,
+                         unsigned int length)
 {
+       unsigned int count, avail;
        unsigned long flags;
-       unsigned int length, i;
 
        spin_lock_irqsave(get_ccwdev_lock(raw->cdev), flags);
-       if (ch == '\t') {
-               length = TAB_STOP_SIZE - (raw->line_pos%TAB_STOP_SIZE);
-               raw->line_pos += length;
-               ch = ' ';
-       } else if (ch == '\n') {
-               length = 1;
-               raw->line_pos = 0;
-       } else {
-               length = 1;
-               raw->line_pos++;
-       }
-       raw3215_make_room(raw, length);
 
-       for (i = 0; i < length; i++) {
-               raw->buffer[raw->head] = (char) _ascebc[(int) ch];
-               raw->head = (raw->head + 1) & (RAW3215_BUFFER_SIZE - 1);
-               raw->count++;
+       count = raw3215_addtext(str, length, raw, RAW3215_COUNT, 0);
+
+       avail = raw3215_make_room(raw, count, con3215_drop);
+       if (avail) {
+               raw3215_addtext(str, length, raw, RAW3215_STORE,
+                               count - avail);
        }
        if (!(raw->flags & RAW3215_WORKING)) {
                raw3215_mk_write_req(raw);
@@ -548,6 +595,14 @@ static void raw3215_putchar(struct raw3215_info *raw, unsigned char ch)
        spin_unlock_irqrestore(get_ccwdev_lock(raw->cdev), flags);
 }
 
+/*
+ * Put character routine for 3215 devices
+ */
+static void raw3215_putchar(struct raw3215_info *raw, unsigned char ch)
+{
+       raw3215_write(raw, &ch, 1);
+}
+
 /*
  * Flush routine, it simply sets the flush flag and tries to start
  * pending IO.
@@ -723,9 +778,43 @@ static struct ccw_device_id raw3215_id[] = {
        { /* end of list */ },
 };
 
+static ssize_t con_drop_store(struct device_driver *dev, const char *buf, size_t count)
+{
+       bool drop;
+       int rc;
+
+       rc = kstrtobool(buf, &drop);
+       if (!rc)
+               con3215_drop = drop;
+       return rc ?: count;
+}
+
+static ssize_t con_drop_show(struct device_driver *dev, char *buf)
+{
+       return sysfs_emit(buf, "%d\n", con3215_drop ? 1 : 0);
+}
+
+static DRIVER_ATTR_RW(con_drop);
+
+static struct attribute *con3215_drv_attrs[] = {
+       &driver_attr_con_drop.attr,
+       NULL,
+};
+
+static struct attribute_group con3215_drv_attr_group = {
+       .attrs = con3215_drv_attrs,
+       NULL,
+};
+
+static const struct attribute_group *con3215_drv_attr_groups[] = {
+       &con3215_drv_attr_group,
+       NULL,
+};
+
 static struct ccw_driver raw3215_ccw_driver = {
        .driver = {
                .name   = "3215",
+               .groups = con3215_drv_attr_groups,
                .owner  = THIS_MODULE,
        },
        .ids            = raw3215_id,
@@ -741,17 +830,10 @@ static void handle_write(struct raw3215_info *raw, const char *str, int count)
        int i;
 
        while (count > 0) {
-               for (i = 0; i < count; i++)
-                       if (str[i] == '\t' || str[i] == '\n')
-                               break;
+               i = min_t(int, count, RAW3215_BUFFER_SIZE - 1);
                raw3215_write(raw, str, i);
                count -= i;
                str += i;
-               if (count > 0) {
-                       raw3215_putchar(raw, *str);
-                       count--;
-                       str++;
-               }
        }
 }
 
@@ -787,7 +869,7 @@ static int con3215_notify(struct notifier_block *self,
        raw = raw3215[0];  /* console 3215 is the first one */
        if (!spin_trylock_irqsave(get_ccwdev_lock(raw->cdev), flags))
                return NOTIFY_DONE;
-       raw3215_make_room(raw, RAW3215_BUFFER_SIZE);
+       raw3215_make_room(raw, RAW3215_BUFFER_SIZE, false);
        spin_unlock_irqrestore(get_ccwdev_lock(raw->cdev), flags);
 
        return NOTIFY_DONE;
@@ -1049,6 +1131,18 @@ static const struct tty_operations tty3215_ops = {
        .start = tty3215_start,
 };
 
+static int __init con3215_setup_drop(char *str)
+{
+       bool drop;
+       int rc;
+
+       rc = kstrtobool(str, &drop);
+       if (!rc)
+               con3215_drop = drop;
+       return rc;
+}
+early_param("con3215_drop", con3215_setup_drop);
+
 /*
  * 3215 tty registration code called from tty_init().
  * Most kernel services (incl. kmalloc) are available at this poimt.