This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

Linux/AM3352: CPU performance issue with getty

Part Number: AM3352

Tool/software: Linux

Hi

I hope someone can help me identify why the performance of my processor gets affected when I am running a specific getty process.

I am running on a custom board based on the beagle bone black with a very cut down root filesystem that uses busybox for as much as possible (no systemd or udev)

I am probably due for updating my kernel (but at present aside from the present confusing behaviour it is working OK fo me)

root@am335x-evm:/dev# uname -a
Linux am335x-evm 4.4.19-gdb0b54cdad #238 PREEMPT Fri Aug 25 16:25:18 AEST 2017 armv7l GNU/Linux

The process that is causing the performance hit is:

389 root 1964 S /sbin/getty 115200 ttyGS0

This is started via the following line in my inittab

us:12345:respawn:/sbin/getty 115200 ttyGS0

It is to provide access via the USB serial connection of a g_multi gadget; this is useful for debug purposes. 

However if I do not open a connection to this on the host PC (e.g via minicom) it appears to hog the CPU.

I have confirmed this via writing a small app that tests the time to execute a tight loop; simply decrementing a counter.

With the getty process running (and no terminal connected from the host PC)

Executing 10 loops of 100000000 decrements
100000000 decrements in 1.576790 sec
100000000 decrements in 1.578677 sec
100000000 decrements in 1.577245 sec
100000000 decrements in 1.580821 sec
100000000 decrements in 1.566301 sec
100000000 decrements in 1.576454 sec
100000000 decrements in 1.737427 sec
100000000 decrements in 1.569567 sec
100000000 decrements in 1.569041 sec
100000000 decrements in 1.553326 sec

Without the getty process running

Executing 10 loops of 100000000 decrements
100000000 decrements in 0.668262 sec
100000000 decrements in 0.667599 sec
100000000 decrements in 0.667559 sec
100000000 decrements in 0.667849 sec
100000000 decrements in 0.669318 sec
100000000 decrements in 0.667540 sec
100000000 decrements in 0.667891 sec
100000000 decrements in 0.667541 sec
100000000 decrements in 0.668885 sec
100000000 decrements in 0.667562 sec

In each case top reports this test process as taking 99% of cpu.
Each decrement takes 4 operations so 2/3 of a second at a cpu frequency of 600000000Hz looks correct for 100000000 loops.

I have confirmed that this is not just the CPU frequency being changed
- there are no changes recorded in root@elle-board:/sys/devices/system/cpu/cpufreq/policy0/stats
- if I do change the frequency from 600000000 to 300000000 the time taken doubles e.g.

100000000 decrements in 1.335705 sec
100000000 decrements in 1.337115 sec
100000000 decrements in 1.336521 sec
100000000 decrements in 1.336904 sec

this is a distinctly different ratio from the slow down seen with the getty running.

There is very little else running on the system: ps reports:

root@elle-board:~/cm# ps
PID USER VSZ STAT COMMAND
1 root 1360 S init [5]
2 root 0 SW [kthreadd]
3 root 0 SW [ksoftirqd/0]
4 root 0 SW [kworker/0:0]
5 root 0 SW< [kworker/0:0H]
6 root 0 SW [kworker/u2:0]
7 root 0 SW [rcu_preempt]
8 root 0 SW [rcu_sched]
9 root 0 SW [rcu_bh]
10 root 0 SW [kdevtmpfs]
11 root 0 SW< [netns]
12 root 0 SW< [perf]
13 root 0 SW [kworker/0:1]
14 root 0 SW< [writeback]
15 root 0 SW< [bioset]
16 root 0 SW< [kblockd]
17 root 0 SW< [edac-poller]
18 root 0 SW< [rpciod]
19 root 0 SW [kswapd0]
20 root 0 SW [fsnotify_mark]
21 root 0 SW< [nfsiod]
22 root 0 SW [kworker/u2:1]
27 root 0 SW< [dma_wq]
28 root 0 SW< [bioset]
29 root 0 SW< [bioset]
30 root 0 SW< [bioset]
31 root 0 SW< [bioset]
32 root 0 SW< [bioset]
33 root 0 SW< [bioset]
34 root 0 SW< [bioset]
35 root 0 SW< [bioset]
36 root 0 SW [spi1]
37 root 0 SW< [bioset]
38 root 0 SW< [bioset]
39 root 0 SW< [bioset]
40 root 0 SW< [bioset]
41 root 0 SW< [bioset]
42 root 0 SW< [bioset]
43 root 0 SW< [bioset]
44 root 0 SW< [kpsmoused]
45 root 0 SW [irq/76-rotary-e]
46 root 0 SW [irq/77-rotary-e]
47 root 0 SW [irq/140-4806000]
48 root 0 SW< [bioset]
49 root 0 SW [mmcqd/0]
50 root 0 SW< [ipv6_addrconf]
51 root 0 SW< [deferwq]
52 root 0 SW [kworker/u2:2]
53 root 0 SW [irq/162-44e0b00]
54 root 0 SW [irq/163-4802a00]
55 root 0 SW< [kworker/0:1H]
56 root 0 SW [jbd2/mmcblk0p2-]
57 root 0 SW< [ext4-rsv-conver]
338 root 0 SW [kworker/0:2]
343 root 0 SW [file-storage]
358 root 2208 S /usr/sbin/dropbear -r /etc/dropbear/dropbear_rsa_host_key -p 22 -B
367 root 1960 S /sbin/syslogd -n -O /var/log/messages
370 root 1960 S /sbin/klogd -n
374 root 1960 S {start_getty} /bin/sh /bin/start_getty 115200 ttyS0
376 root 2372 S -sh
389 root 1964 S /sbin/getty 115200 ttyGS0
391 root 2372 R ps

I can work around this by not launching the getty process; but obviously then I cannot use the USB gadget for debug.

I would be grateful for any insight in to why this might cause these symptoms
- and for any solution that might allow me to make use of the com port if I needed to

Thanks for the help
Best regards,
Richard

  • The software team have been notified. They will respond here.
  • Hi Richard,

    I suggest you to use the last Processor SDK version v04.01.00.06 and check whether the same issue is observed.
    If the issue is still exists I suggest you to change priority (nice value) of 'getty' and your application processes. For example you can use 'renice' command.

    renice -n 19 -p PID_of_getty
    renice -n -20 -p PID_of_your_app


    BR
    Tsvetolin Shulev

  • Thanks Tsvetolin 

    The renice has made no difference (I neglected to mention previously that I had tried launching my test process at -20)

    I will start trying to upgrade the SDK

    Can you please explain what differences have been made to the operation of getty or the USB serial device handling that might have impacted the behaviour?

    - it might be that I can source patches for those (as an interim step);  as it is a very slow process to update the full SDK & tools etc 

    Thanks

    Richard

  • Hi Tsvetolin

    I upgraded my SDK to 04 01 00 06.

    The behaviour is identical.

    If I want a getty to start on the USB serial node (ttyGS0) I need to have something attach to it from the other side (the host PC) otherwise the CPU performance is terrible.

    You can see the change in performance below when I launch a minicom terminal on my host

    executing 100 loops of 100000000 decrements
    100000000 decrements in 1.528226 sec
    100000000 decrements in 1.527044 sec
    100000000 decrements in 1.526758 sec
    100000000 decrements in 1.528994 sec
    100000000 decrements in 1.529349 sec
    100000000 decrements in 1.527789 sec
    100000000 decrements in 1.527521 sec
    100000000 decrements in 1.530405 sec
    100000000 decrements in 1.528516 sec
    100000000 decrements in 1.526883 sec
    100000000 decrements in 1.527207 sec
    100000000 decrements in 1.527600 sec
    100000000 decrements in 1.527567 sec
    100000000 decrements in 1.527359 sec
    100000000 decrements in 1.527364 sec
    100000000 decrements in 1.527445 sec
    100000000 decrements in 1.527572 sec
    100000000 decrements in 1.527757 sec
    100000000 decrements in 1.527552 sec
    100000000 decrements in 1.527521 sec
    100000000 decrements in 1.527517 sec
    100000000 decrements in 1.527636 sec
    100000000 decrements in 1.527196 sec
    100000000 decrements in 1.527554 sec
    100000000 decrements in 1.527522 sec
    100000000 decrements in 1.528081 sec
    100000000 decrements in 1.527800 sec
    100000000 decrements in 1.528169 sec
    100000000 decrements in 1.527518 sec
    100000000 decrements in 1.527327 sec
    100000000 decrements in 1.527318 sec
    100000000 decrements in 1.527793 sec
    100000000 decrements in 1.527763 sec
    100000000 decrements in 0.845382 sec   // Minicom launched
    100000000 decrements in 0.669116 sec
    100000000 decrements in 0.668499 sec
    100000000 decrements in 0.668510 sec
    100000000 decrements in 0.668731 sec
    100000000 decrements in 0.668523 sec
    100000000 decrements in 0.668476 sec
    100000000 decrements in 0.669157 sec
    100000000 decrements in 0.669991 sec
    100000000 decrements in 0.668498 sec
    100000000 decrements in 0.668981 sec
    100000000 decrements in 0.668493 sec
    100000000 decrements in 0.668461 sec
    100000000 decrements in 0.668913 sec
    100000000 decrements in 0.668541 sec
    100000000 decrements in 0.668534 sec
    100000000 decrements in 0.668691 sec
    100000000 decrements in 0.668501 sec
    100000000 decrements in 0.668479 sec
    100000000 decrements in 0.669117 sec
    100000000 decrements in 0.668485 sec
    100000000 decrements in 0.668488 sec
    100000000 decrements in 0.669001 sec
    100000000 decrements in 0.668479 sec
    100000000 decrements in 0.668484 sec
    100000000 decrements in 0.668930 sec
    100000000 decrements in 0.668894 sec
    100000000 decrements in 0.668524 sec
    100000000 decrements in 0.668873 sec
    100000000 decrements in 0.668483 sec
    100000000 decrements in 0.668551 sec
    100000000 decrements in 0.668482 sec
    100000000 decrements in 0.668819 sec
    100000000 decrements in 0.668487 sec
    100000000 decrements in 0.668510 sec
    100000000 decrements in 0.668755 sec
    100000000 decrements in 0.668472 sec
    100000000 decrements in 0.668519 sec
    100000000 decrements in 0.668813 sec
    100000000 decrements in 0.668486 sec
    100000000 decrements in 0.668488 sec
    

    There really is very little running:

    root@elle-board:~/cm# ps
      PID USER       VSZ STAT COMMAND
        1 root      1964 S    init
        2 root         0 SW   [kthreadd]
        3 root         0 SW   [ksoftirqd/0]
        4 root         0 SW   [kworker/0:0]
        5 root         0 SW<  [kworker/0:0H]
        7 root         0 SW   [rcu_preempt]
        8 root         0 SW   [rcu_sched]
        9 root         0 SW   [rcu_bh]
       10 root         0 SW<  [lru-add-drain]
       11 root         0 SW   [kdevtmpfs]
       12 root         0 SW<  [netns]
       13 root         0 SW   [kworker/0:1]
       14 root         0 SW   [oom_reaper]
       15 root         0 SW<  [writeback]
       16 root         0 SW   [kcompactd0]
       17 root         0 SW<  [bioset]
       18 root         0 SW<  [kblockd]
       19 root         0 SW<  [edac-poller]
       20 root         0 SW<  [watchdogd]
       21 root         0 SW<  [rpciod]
       22 root         0 SW<  [xprtiod]
       23 root         0 SW   [kswapd0]
       24 root         0 SW<  [nfsiod]
       25 root         0 SW   [kworker/u2:1]
       30 root         0 SW<  [bioset]
       31 root         0 SW<  [bioset]
       32 root         0 SW<  [bioset]
       33 root         0 SW<  [bioset]
       34 root         0 SW<  [bioset]
       35 root         0 SW<  [bioset]
       36 root         0 SW<  [bioset]
       37 root         0 SW<  [bioset]
       38 root         0 SW   [spi1]
       39 root         0 SW<  [bioset]
       40 root         0 SW<  [bioset]
       41 root         0 SW<  [bioset]
       42 root         0 SW<  [bioset]
       43 root         0 SW<  [bioset]
       44 root         0 SW<  [bioset]
       45 root         0 SW<  [bioset]
       46 root         0 SW   [irq/76-rotary-e]
       47 root         0 SW   [irq/77-rotary-e]
       48 root         0 SW   [irq/140-4806000]
       49 root         0 SW<  [bioset]
       50 root         0 SW   [mmcqd/0]
       51 root         0 SW<  [ipv6_addrconf]
       53 root         0 SW   [irq/162-44e0b00]
       55 root         0 SW   [irq/163-4802a00]
       56 root         0 SW<  [kworker/0:1H]
       57 root         0 SW   [jbd2/mmcblk0p2-]
       58 root         0 SW<  [ext4-rsv-conver]
      398 root         0 SW   [kworker/u2:2]
      421 root         0 SW   [file-storage]
      436 root      2204 S    /usr/sbin/dropbear -r /etc/dropbear/dropbear_rsa_host_key -p 22 -B
      447 root      1964 S    /sbin/syslogd -n -O /var/log/messages
      449 root      1964 S    /sbin/klogd -n
      452 root      2396 S    -sh
      468 root      1964 S    /sbin/getty 115200 ttyGS0
      470 root         0 SW   [kworker/u2:0]
      474 root      2400 R    ps
    

    I would be grateful if you could suggest something that might shed some light on what might be going on?

    Thanks for the help.

    Richard

  • I should also note that the renice had no effect on the presented values
    - it did however make the "ps" command execute a(and display its results) much more slowly

    Thanks again
    Richard