Originally published November 22, 2019 @ 5:38 pm

I have discussed atop previously but concentrated primarily on how to run it and how to collect data. Now I’d like to spend some time talking about ways to analyze the data collected with atop.

Included with the atop package is atopsar – a utility design to extract data from the atop logs and massage it in various ways. Let’s take a look at a few simple examples. And a few not so simple ones as well.

Processes

Identify top-five most frequently executed processes during specified time frame

atop -b 07:23:00 -e 07:24:00 -r ${atop_log} -P PRG | \
grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | \
sort | uniq -c | sort -k1rn | head -5

  19179 grep
  16895 awk
  16867 udevadm
   4226 dmsetup
   2985 oracle

Count the number of times a particular process has been detected during specified time frame

atop -b 07:20:00 -e 07:25:00 -r ${atop_log} -P PRG | \
egrep "mpath-iosched" | awk '{print $5}' | uniq -c -w5

    981 07:20:00
   1071 07:21:10
    621 07:22:00
  18684 07:23:00
    270 07:24:10
   3861 07:25:00

Generate a chart of the number of instances of a particular process over time

atop -b 07:00:00 -e 07:30:00 -r ${atop_log} -P PRG | \
egrep "mpath-iosched" | awk '{print $5}' | uniq -c -w8 | \
gnuplot -e "set terminal dumb 80 20; unset key; set style data labels; set xdata time; set xlabel 'Time'; set ylabel 'mpath-iosched'; set timefmt '%H:%M:%S'; plot '-' using 2:1:ytic(1) with histeps"

  mpath-iosched
   15589 +++-+-+-+-+-+-+-+--+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-*--+-+-+-+-+-+-+-+++
         +     +     +      +     +     +     +     +     *      +     +     +
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
         |                                                *                  |
    2853 ++                                     *        **       ***       ++
    2151 ++                    *   *            *        **   **  * *       ++
    1558 ***   +**   +     *+  *  +***  +     +**   *    **   ** ** *****   ++
     119 *********************************************************-+-+-+***+++
       00:00 03:00 06:00  09:00 12:00 15:00 18:00 21:00 24:00  27:00 30:00 33:00
                                         Time

Similar to the previous example, but output chart to PNG

atop -r ${atop_log} -P PRG | egrep "mpath-iosched" | awk '{print $5}' | uniq -c -w8 | \
gnuplot -e "set title 'mpath-iosched.sh instance count'; set offset 1,1,1,1; set autoscale xy; set mxtics; set mytics; \
set style line 12 lc rgb '#ddccdd' lt 1 lw 1.5; set style line 13 lc rgb '#ddccdd' lt 1 lw 0.5; set grid xtics mxtics ytics mytics \
back ls 12, ls 13; set terminal png size 1920,1280 enhanced font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,10'; set output 'plot_$(date +'%Y-%m-%d_%H%M%S')_${RANDOM}.png'; \
set style data labels; set xdata time; set xlabel 'Time' font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set ylabel 'Count' \
font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set timefmt '%H:%M:%S'; plot '-' using 2:1 with histeps"

Generate an overall process count chart for the entire available time frame

atop -r ${atop_log} -P PRG | awk '{print $5}' | uniq -c -w8 | \
gnuplot -e "set title 'Process Count'; set offset 1,1,1,1; set autoscale xy; set mxtics; set mytics; \
set style line 12 lc rgb '#ddccdd' lt 1 lw 1.5; set style line 13 lc rgb '#ddccdd' lt 1 lw 0.5; set grid xtics mxtics ytics mytics \
back ls 12, ls 13; set terminal png size 1920,1280 enhanced font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,10'; set output 'plot_$(date +'%Y-%m-%d_%H%M%S')_${RANDOM}.png'; \
set style data labels; set xdata time; set xlabel 'Time' font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set ylabel 'Count' \
font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set timefmt '%H:%M:%S'; plot '-' using 2:1 with histeps"

Identify top-ten most frequently executed binaries from /sbin or /usr/sbin during specified time frame

for i in $(atop -b 07:23:00 -e 07:24:00 -r ${atop_log} -P PRG | \
grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | sort | uniq -c | \
sort -k1rn | head -10 ); do  which "${i}" 2>/dev/null | grep sbin; done

/sbin/udevadm
/sbin/dmsetup
/sbin/blkid
/sbin/kpartx

Find out when the process creation rate, or the total number of processes, or the number of processes in uninterruptable sleep state exceeded certain limits during specified time frame

atopsar -b 07:21:00 -e 07:30:00 -r ${atop_log} -P | \
awk -v i=500 -v j=10000 -v k=20 '$2 > i || $4 > j || $8 > k'

prodoracle01  2.6.32-754.18.2.el6.x86_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21
-------------------------- analysis date: 2019/11/18 --------------------------
07:21:00  clones/s pexit/s  curproc curzomb    thrrun thrslpi thrslpu _procthr_
07:23:30   1341.10 1458.30    15542       2         2    4834     170
07:23:40   7096.00 7123.40    73446       1         5    5774       1
07:23:54   4112.29    0.29     1447       1         7    5774       1
07:25:40    489.50 1302.80    22799       1        21   13256       1
07:26:40    208.25  135.50    10002       1         7   13597       1
07:26:50    184.10  134.30    11538       1        16   14312       1
07:27:01     38.09   53.45    10992       1        22   14613       1
07:27:10    155.89   28.33    10742       1        19   14809       1
07:27:20     73.60   52.10    11652       1        17   15264       1
07:27:30    153.70  495.10    17652       1        22   16673       3
07:27:52    244.55    0.09    12171       1        18   16679       2
07:28:00    340.38 1961.62    33875       1        18   21694       2
07:29:27    214.66   47.57    23521       1        18   23166       1
07:29:59    182.47  201.75    28482       1        16   25596       2
07:30:59    154.47   17.10    22958       1        17   26070       1

Disks and Volumes

Identify disks with over 90% activity during specified time frame

atopsar -b 07:23:00 -e 07:24:00 -r ${atop_log} -d | \
egrep '^[0-9].*|(9[0-9]|[0-9]{3,})%'

07:23:00  disk           busy read/s KB/read  writ/s KB/writ avque avserv _dsk_
07:23:10  sda              0%    0.1     4.0    19.5     7.0   5.4   0.04 ms
07:23:20  sda              0%    0.1   128.0    26.5     7.9  28.0   0.00 ms
07:23:30  sda             34%  682.7    11.7     8.9    18.7  96.0   0.49 ms
07:23:40  sda            101% 1413.3    23.3     0.8     6.5 154.4   0.71 ms
07:23:54  sda             88% 1125.2    17.6    13.6    12.9  89.7   0.77 ms
07:24:00  sda             13%  573.8    46.7    66.9    22.6   3.0   0.20 ms
07:24:10  sda              0%    3.4    24.5    16.7    14.5   1.9   0.24 ms
07:24:20  sda              3%  149.0    43.0     9.4    11.3   2.7   0.16 ms
07:24:30  sda              5%  219.9    86.4    26.7    32.4   2.4   0.20 ms
07:24:40  sda              0%    0.8    31.0     8.8    15.0   1.3   0.33 ms
07:24:50  sda              0%    0.4    25.0     8.5    14.1   1.0   0.27 ms

Identify processes responsible for most disk I/O during specified time frame

atopsar -b 07:21:00 -e 07:24:00 -r ${atop_log} -D | \
sed 's/\%//g' | awk -v k=50 '$4 > k || $8 > k || $12 > k' | \
sed -r 's/([0-9]{1,})/%/5;s/([0-9]{1,})/%/7;s/([0-9]{1,})/%/9'

prodoracle01  2.6.32-754%.18.2%.el6.x86%_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21
07:21:00    pid command  dsk |   pid command  dsk |   pid command  dsk_top3_
07:21:10      1 init      95% | 30953 oracle     3% | 30944 oracle     1%
07:22:40  25016 oracle    66% |   411 oracle    15% | 30959 oracle     9%
07:22:50  30878 oracle    53% | 30959 oracle    46% | 11022 oracle     0%
07:23:10  30968 oracle    98% | 20958 oracle     0% |  8676 oracle     0%
07:23:30      1 init      78% |  4289 oracle    13% | 30878 oracle     7%
07:23:40      1 init     100% | 17612 oracle     0% | 30878 oracle     0%
07:23:54  25016 oracle   100% | 31428 atop       0% |  8676 oracle     0%
07:24:00  25016 oracle    71% | 30968 oracle    15% | 22938 authoriz  13%
07:24:40  16719 oracle    51% | 30947 oracle    48% | 28678 oracle     0%

Identify periods of heavy swap activity during specified time frame

atopsar -b 06:00:00 -e 07:30:00 -r ${atop_log} -s | \
awk -v k=1000 '$2 > k || $3 > k || $4 > k'

prodoracle01  2.6.32-754.18.2.el6.x86_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21
-------------------------- analysis date: 2019/11/18 --------------------------
06:00:00  pagescan/s   swapin/s  swapout/s        commitspc  commitlim   _swap_
06:18:40     7264.00       0.00     556.10           53269M     28399M
06:18:50    48777.60       0.80    1117.70           53343M     28399M
06:19:00     2188.80       0.80      28.50           51276M     28399M
07:23:30        0.00    2057.40       0.00           51129M     28399M
07:23:40        0.00    8141.70       0.00           56598M     28399M
07:23:54        0.00    4778.57       0.00           53349M     28399M

Make a chart of pagescan, swapin, and swapout

f="$(mktemp)" && atopsar -b 06:00:00 -e 07:30:00 -r ${atop_log} -s | awk '{print $1,$2,$3,$4}' > "${f}"
gnuplot -e "set title 'Swap Activity'; set offset 1,1,1,1; set autoscale xy; set mxtics; set mytics; \
set style line 12 lc rgb '#ddccdd' lt 1 lw 1.5; set style line 13 lc rgb '#ddccdd' lt 1 lw 0.5; set grid xtics mxtics ytics mytics \
back ls 12, ls 13; set terminal png size 1920,1280 enhanced font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,10'; set output 'plot_$(date +'%Y-%m-%d_%H%M%S')_${RANDOM}.png'; \
set style data labels; set xdata time; set xlabel 'Time' font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set ylabel 'Count' \
font '/usr/share/fonts/liberation/LiberationSans-Regular.ttf,8'; set timefmt '%H:%M:%S'; \
plot '< cat ${f}' using 1:2 with histeps title 'pagescan/s', '' using 1:3 with histeps title 'swapin/s', '' using 1:4 with histeps title 'swapout/s';"
/bin/rm "${f}"

Identify logical volumes with high activity or high average queue during specified time frame

atopsar -b 07:21:00 -e 07:24:00 -r ${atop_log} -l -S | \
sed 's/\%//g' | awk -v k=50 -v j=100 '$3 > k || $8 > j' | \
sed -r 's/([0-9]{1,})/%/4'

prodoracle01  2.6.32%-754.18.2.el6.x86_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21
-------------------------- analysis date: 2019/11/18 --------------------------
07:21:00  disk           busy read/s KB/read  writ/s KB/writ avque avserv _lvm_
07:21:20  rootvg-var       0%    0.0     0.0    49.2     4.0 108.5   0.00 ms
07:21:50  rootvg-var       0%    0.0     0.0    69.0     4.0 113.5   0.00 ms
07:23:30  rootvg-swap     34% 2076.0     4.0     0.0     0.0 350.8   0.16 ms
07:23:40  rootvg-swap    101% 8190.4     4.0     0.0     0.0 757.7   0.12 ms
07:23:40  rootvg-var      52%    0.0     0.0    12.7     4.0 116.1  41.38 ms
07:23:40  rootvg-opt     101%    0.1     4.0    22.9     4.0  94.9  43.67 ms
07:23:54  rootvg-swap     88% 4833.1     4.0     0.0     0.0 203.6   0.18 ms
07:23:54  rootvg-var      76%    0.1     4.0     0.7     4.0 110.5 950.18 ms
07:23:54  rootvg-opt      78%    9.6    32.8    17.9     4.0  96.2  28.46 ms
07:24:00  rootvg-var       0%    0.0     0.0   318.3     4.0 159.2   0.00 ms

Processors

Identify processes consuming more than half of all available CPUs during specified time frame

(( k = $(grep -c proc /proc/cpuinfo) / 2 * 100 ))
atopsar -b 07:22:00 -e 07:24:00 -r ${atop_log} -O | \
sed 's/\%//g' | awk -v k=$k '$4 > k || $8 > k || $12 > k' | \
sed -r 's/([0-9]{1,})/%/5;s/([0-9]{1,})/%/7;s/([0-9]{1,})/%/9'

prodoracle01  2.6.32-754%.18.2%.el6.x86%_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21
-------------------------- analysis date: 2019/11/18 --------------------------
07:22:00    pid command  cpu |   pid command  cpu |   pid command  cpu_top3_
07:23:40  21668 oracle   20940% | 22561 oracle   20231% | 22552 oracle   19981%
07:24:10  22938 authoriz 1361% |   411 oracle    24% | 30968 oracle    17%
07:24:20  22938 authoriz 1347% | 10915 oracle    66% |  4277 oracle    19%
07:24:30  22938 authoriz 1275% |  4283 oracle    48% |  4277 oracle    45%
07:24:40  22938 authoriz 1384% | 16719 oracle    22% | 30947 oracle    21%
07:24:50  22938 authoriz 1306% | 20958 oracle    38% |  4023 oracle    32%

Memory

Identify time of peak memory utilization during the specified time frame

atopsar -b 07:00:00 -e 07:30:00 -r ${atop_log} -m -R 1 | \
awk 'NR<7{print $0;next}{print $0| "sort -k 3,3"}' | head -15

prodoracle01  2.6.32-754.18.2.el6.x86_64  #1 SMP Thu Jul 25 17:15:34 EDT 2019  x86_64  2019/11/21

-------------------------- analysis date: 2019/11/18 --------------------------

07:00:00  memtotal memfree buffers cached dirty slabmem  swptotal swpfree _mem_

07:18:40   128934M   2015M    406M  1492M    2M   1719M    16383M   5839M
07:18:30   128934M   2272M    406M  1492M    2M   1718M    16383M   5839M
07:03:40   128934M   2419M    401M  1442M    1M   1714M    16383M   5833M
07:18:20   128934M   2426M    406M  1491M    3M   1717M    16383M   5839M
07:03:50   128934M   2439M    401M  1443M    1M   1715M    16383M   5833M
07:04:00   128934M   3049M    401M  1444M    2M   1714M    16383M   5833M
07:08:40   128934M   3301M    404M  1457M    3M   1721M    16383M   5834M
07:18:10   128934M   3425M    406M  1491M    1M   1717M    16383M   5839M

Comparing apples and oysters

When it comes to system performance analysis, being able to see the complete picture is crucial. Just looking at memory, or disk I/O, or CPU activity separately may only tell you that something happened. But you already knew this.

Here is a basic example of joining output of two separate instances of `atoprar` based on the timestamp. In this example we can view the time, the number of running processes, the processes generating most I/O, and the percentage of I/O they’re responsible for:

b="07:21:00"; e="07:24:00"
join -j 1 -o 1.1,1.2,2.2,2.3 \
> <(atopsar -b ${b} -e ${e} -r ${atop_log} -P | awk '{print $1,$4}' | awk 'NR>7{print $0;next}') 2>/dev/null \
> <(atopsar -b ${b} -e ${e} -r ${atop_log} -D | awk '{print $1,$3,$4}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> (echo "Time Procs App App_I/O" && cat) | column -t

Time      Procs  App     App_I/O
07:21:20  1334   oracle  48%
07:21:30  2313   oracle  35%
07:21:40  1498   oracle  32%
07:21:50  1810   oracle  32%
07:22:00  1890   oracle  28%
07:22:10  873    oracle  50%
07:22:20  624    oracle  30%
07:22:30  1132   oracle  34%
07:22:40  2708   oracle  66%
07:22:50  1015   oracle  53%
07:23:00  1403   oracle  49%
07:23:10  778    oracle  98%
07:23:20  641    oracle  43%
07:23:30  15542  init    78%
07:23:40  73446  init    100%
07:23:54  1447   oracle  100%
07:24:00  1885   oracle  71%
07:24:10  1017   oracle  47%
07:24:20  1887   oracle  38%
07:24:30  2605   oracle  28%
07:24:40  1060   oracle  51%
07:24:50  1681   oracle  38%

The join command allows you to merge two files (or outputs of two commands) based on a common matching field – a timestamp in our case.

If you need to merge more than two files, things can get a bit tricky. Essentially, you merge the first two and the output becomes file #1. Then you pipe that output plus your new file #2 into the second merge. And so on.

Here’s an example of five nested joins providing side-by-side view of the timestamp, the number of processes, application with heavy I/O, the amount of I/O by this application, memory/disk swapping in and out, activity on the system disk, amount of free memory, and average system load.

b="07:21:00"; e="07:24:00"
join -j 1 -o 1.1,1.2,2.2,2.3 \
> <(atopsar -b ${b} -e ${e} -r ${atop_log} -P | awk '{print $1,$4}' | awk 'NR>7{print $0;next}') 2>/dev/null \
> <(atopsar -b ${b} -e ${e} -r ${atop_log} -D | awk '{print $1,$3,$4}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> join -j 1 -o 1.1,1.2,1.3,1.4,2.2,2.3 \
> - <(atopsar -b ${b} -e ${e} -r ${atop_log} -s | awk '{print $1,$3,$4}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> join -j 1 -o 1.1,1.2,1.3,1.4,1.5,1.6,2.2,2.3 \
> - <(atopsar -b ${b} -e ${e} -r ${atop_log} -d | egrep 'sda\b' | awk '{print $1,$2,$3}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> join -j 1 -o 1.1,1.2,1.3,1.4,1.5,1.6,1.7,1.8,2.2 \
> - <(atopsar -b ${b} -e ${e} -r ${atop_log} -m -R 1 | awk '{print $1,$3}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> join -j 1 -o 1.1,1.2,1.3,1.4,1.5,1.6,1.7,1.8,1.9,2.2 \
> - <( atopsar -b ${b} -e ${e} -r ${atop_log} -p | awk '{print $1,$5}' | awk 'NR>7{print $0;next}') 2>/dev/null | \
> (echo "Time Procs App App_I/O S/in S/out BusyDisk HowBusy MemFree Load" && cat) | column -t

Time      Procs  App     App_I/O  S/in     S/out  BusyDisk  HowBusy  MemFree  Load
07:22:20  624    oracle  30%      1.60     0.00   sda       0%       4035M    1.75
07:22:30  1132   oracle  34%      0.00     0.00   sda       0%       4032M    1.78
07:22:40  2708   oracle  66%      0.80     0.00   sda       0%       4032M    1.66
07:22:50  1015   oracle  53%      0.10     0.00   sda       0%       4035M    1.71
07:23:00  1403   oracle  49%      0.00     0.00   sda       0%       4005M    1.76
07:23:10  778    oracle  98%      0.10     0.00   sda       0%       4012M    1.65
07:23:20  641    oracle  43%      0.00     0.00   sda       0%       3994M    1.55
07:23:30  15542  init    78%      2057.40  0.00   sda       34%      3937M    17.80
07:23:40  73446  init    100%     8141.70  0.00   sda       101%     4757M    39.27
07:23:54  1447   oracle  100%     4778.57  0.00   sda       88%      6763M    40.39
07:24:00  1885   oracle  71%      5.50     0.00   sda       13%      6567M    34.41
07:24:10  1017   oracle  47%      1.40     0.00   sda       0%       6558M    29.36
07:24:20  1887   oracle  38%      2.00     0.00   sda       3%       6393M    25.46
07:24:30  2605   oracle  28%      0.80     0.00   sda       5%       6077M    24.10
07:24:40  1060   oracle  51%      3.00     0.00   sda       0%       5972M    20.86
07:24:50  1681   oracle  38%      2.40     0.00   sda       0%       5810M    18.73

Sometimes you see a drastic change in system behavior and wonder if some new process starting up on the server could’ve been the reason. However, with thousands of running processes, figuring out what started and what exited can be difficult.

Here’s a small script that will go through your atop log frame by frame; get a list of running process names; and compare that list to the previous frame. It will then show you what appeared and what disappeared. There are a few variables in the script. The obvious ones have to do with the starting time, the frame interval (should probably match the interval used to record the log), and the number of frames to analyze.

There is also the ${cutoff} variable. When looking at the running process, sometimes you may see a great many instances of the same command (say, a couple thousand instances of awk, sed, and grep that come from some hyperactive script). You probably want to filter those out and concentrate on more important things. The script will only look at processes that have no more than ${cutoff} running instances.

#!/bin/bash

configure() {
  atop_log=/opt/tmp/atop_log/atop_prodoracle01_2019-11-18_051624.log
  timestart="Mon Nov 18 07:15:00 EST 2019"
  timeinterval="+10 seconds"
  timesteps="100"
  i=1
  w=160
  cutoff=10
}

analyze() {
  # new
  new="$(diff --new-line-format="" --unchanged-line-format="" \
  <(atop -b ${t2} -e ${t2} -r ${atop_log} -P PRG | grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | sort | uniq -c | sort -k1n | awk -v cutoff=$cutoff '$1 < cutoff {print $2}' | sort -u) \
  <(atop -b ${t1} -e ${t1} -r ${atop_log} -P PRG | grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | sort | uniq -c | sort -k1n | awk -v cutoff=$cutoff '$1 < cutoff {print $2}' | sort -u) | xargs)"

  # gone
  gone="$(diff --new-line-format="" --unchanged-line-format="" \
  <(atop -b ${t1} -e ${t1} -r ${atop_log} -P PRG | grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | sort | uniq -c | sort -k1n | awk -v cutoff=$cutoff '$1 < cutoff {print $2}' | sort -u) \
  <(atop -b ${t2} -e ${t2} -r ${atop_log} -P PRG | grep -oP "(?<=\()[[:alnum:]]{1,}(?=\))" | sort | uniq -c | sort -k1n | awk -v cutoff=$cutoff '$1 < cutoff {print $2}' | sort -u) | xargs)"
}

# RUNTIME
configure
while [ ${i} -le ${timesteps} ]
do
  if [ ${i} -eq 1 ]
  then
    pr -w ${w} -m -t <(echo "FROM     - TO") <(echo -e "STARTED") <(echo -e "\tENDED")
    eval printf %.0s- '{1..'"${w:-$(tput cols)}"\}; echo
    t1=$(date -d"${timestart}" +'%H:%M:%S')
    t2=$(date -d"${timestart} ${timeinterval}" +'%H:%M:%S')
    timestart="$(date -d"${timestart} ${timeinterval}")"
  else
    t1="${t2}"
    t2=$(date -d"${timestart} ${timeinterval}" +'%H:%M:%S')
    timestart="$(date -d"${timestart} ${timeinterval}")"
  fi
  echo -ne "${t1} - ${t2}\t"
  analyze
  pr -s'|' -w ${w} -m -t <(echo "${new}") <(echo "${gone}")
  (( i = i + 1 ))
done

And here’s sample output:

FROM     - TO           STARTED                       ENDED
-----------------------------------------------------------------------------------
07:15:00 - 07:15:10                                  |
07:15:10 - 07:15:20                                  |
07:15:20 - 07:15:30                                  |
07:15:30 - 07:15:40                                  |
07:15:40 - 07:15:50                                  |
07:15:50 - 07:16:00     auditd cmascsid cmathreshd...|bpcd cmasasd getconf nfsd4 py
07:16:00 - 07:16:10                                  |
07:16:10 - 07:16:20                                  |
07:16:20 - 07:16:30                                  |
07:16:30 - 07:16:40                                  |
07:16:40 - 07:16:50                                  |
07:16:50 - 07:17:00     bpcd gmond hald python rpcbin|cmascsid cmathreshd ons