a   t r a c e   o f   a   s y s t e m   d o i n g   n o t h i n g

At the end of the work day, a software researcher colleague was tasked with closing all of their open programs, letting the computer wind down. Once the software activity of the day had stopped, our colleague ran a program that recorded the software activity of the kernel for one second. During this one second the human had no interaction with the computer.

The subject of our listening is a laptop, generally a tool meant for, or at least marketed for, efficiency and productivity. Its operating system is an installation of Ubuntu 18.04.4 LTS with the 5.3.0-40-generic kernel running on an i7 6820HQ (2.7 GHz) CPU. Running quite a stripped down system with a minimalist window manager, this system might be calmer than most.

Many things happen in the software heart of the computer, the kernel, and there are many ways to measure them. One can trace the communication between applications and the operating system (so called system calls) or measure the temperature of the components fluctuate with power use. This work uses the ftrace tool which, among other things, records function calls inside the Linux kernel. These function calls do not paint a complete picture of all that is happening inside the computer. Yet, since it is virtually impossible to obtain such an exhaustive observation of every aspect of the system at the same time, it serves as a good approximation.

Software terminology


  • The kernel is the very core part of the operating system. It is always in memory, always ready to act, coordinate, serve and rule over the applications.
  • Functions are small sections of code. When a function wants to trigger the running of the code contained in another function it is said to call that function, resulting in a function call.

This is a glimpse into the invisible imperceptible core of, and a kind of background to, our computing experience.

"The data hidden in our perceptual "blind spot" contains worlds waiting to be explored, if we choose to shift our focus there. Today's digital technology enables artists to explore new territories for content by capturing and examining the area beyond the boundary of "normal" functions and
uses of software."


Kim Cascone, The Aesthetics of Failure: "Post-Digital" Tendencies in Contemporary Computer Music

Where is tranquillity in 199 389 events in a second? First off, reading the trace we notice that some of the activity is caused by the tracing script starting and stopping, some of it is caused by the `sleep` program that we use to count to 1 second before stopping, and a lot of it is caused by the `<idle>` process, sometimes called `swapper` or process 0. This is a process whose job is to do nothing at all in an infinite loop and runs with the lowest possible priority only if nothing else needs running.

Secondly, since there are 1 000 000 microseconds in a second, only 199 389 events and many events occur within the same microsecond, a majority of these microseconds have no function call happening within them.

During the trace, the laptop made no sound, the screen showed nothing but the most bare-bones user interface and there was no human initiated tasks going on in the background. Thus, the trace reflects the activity in the computer when it does not actively perform any work and is undisturbed by any human.

Tracing the activity of the kernel for one second, we were left with a sequence containing 199 389 software events timestamped with microsecond accuracy. This accuracy was not sufficient to distinguish the individual starting point of every function call since many microseconds contain several function calls within them. This already is a demonstration of the incredible speed of the events we are measuring, and how far it is from a human perception of time.

While reading through all of this data could certainly be a meditative experience, discovering it as tranquil seems easier experienced through listening.

12:01:07-12:35:36            254 512 μs - 266 682 μs

# tracer: function
#
# entries-in-buffer/entries-written: 199344/3650406   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
 ftrace_test_scr-2638  [007] .... 132339.890885: mutex_unlock <-rb_simple_write
 ftrace_test_scr-2638  [007] .... 132339.890887: __fsnotify_parent <-vfs_write
 ftrace_test_scr-2638  [007] .... 132339.890888: fsnotify <-vfs_write
 ftrace_test_scr-2638  [007] .... 132339.890888: __sb_end_write <-vfs_write
 ftrace_test_scr-2638  [007] .... 132339.890889: syscall_slow_exit_work <-do_syscall_64
 ftrace_test_scr-2638  [007] .... 132339.890889: sys_exit: NR 1 = 2
 ftrace_test_scr-2638  [007] .... 132339.890890: sys_write -> 0x2
 ftrace_test_scr-2638  [007] d... 132339.890891: fpregs_assert_state_consistent <-do_syscall_64
 ftrace_test_scr-2638  [007] d... 132339.890891: switch_fpu_return <-do_syscall_64
 ftrace_test_scr-2638  [007] d... 132339.890892: x86_fpu_regs_activated: x86/fpu: 00000000b9fa274d load: 1 xfeatures: 2 xcomp_bv: 800000000000001f
 ftrace_test_scr-2638  [007] d... 132339.890895: do_syscall_64 <-entry_SYSCALL_64_after_hwframe
 ftrace_test_scr-2638  [007] .... 132339.890896: syscall_trace_enter <-do_syscall_64
 ftrace_test_scr-2638  [007] .... 132339.890896: sys_enter: NR 33 (b, 1, 2, 1b6, 55c879282b2b, 55c87aefab22)
 ftrace_test_scr-2638  [007] .... 132339.890897: sys_dup2(oldfd: b, newfd: 1)
 ftrace_test_scr-2638  [007] .... 132339.890897: __x64_sys_dup2 <-do_syscall_64
 ftrace_test_scr-2638  [007] .... 132339.890898: ksys_dup3 <-__x64_sys_dup2
 ftrace_test_scr-2638  [007] .... 132339.890898: _raw_spin_lock <-ksys_dup3
 ftrace_test_scr-2638  [007] .... 132339.890898: expand_files <-ksys_dup3
 ftrace_test_scr-2638  [007] .... 132339.890899: do_dup2 <-ksys_dup3
 ftrace_test_scr-2638  [007] .... 132339.890899: filp_close <-do_dup2

A computer calm, when it sits undisturbed doing nothing in particular for a single second.



The following is an excerpt from the 16.9 MiB large trace:

 irq/141-iwlwifi-640   [005] d... 132340.412357: dequeue_top_rt_rq <-dequeue_rt_stack
 irq/141-iwlwifi-640   [005] d... 132340.412357: cpupri_set <-dequeue_rt_stack
 irq/141-iwlwifi-640   [005] d... 132340.412357: update_rt_migration <-dequeue_rt_stack
 irq/141-iwlwifi-640   [005] d... 132340.412357: enqueue_top_rt_rq <-dequeue_task_rt
 irq/141-iwlwifi-640   [005] d... 132340.412357: pick_next_task_stop <-__schedule
 irq/141-iwlwifi-640   [005] d... 132340.412357: pick_next_task_dl <-__schedule
 irq/141-iwlwifi-640   [005] d... 132340.412357: pick_next_task_rt <-__schedule
 irq/141-iwlwifi-640   [005] d... 132340.412357: pull_rt_task <-pick_next_task_rt
 irq/141-iwlwifi-640   [005] d... 132340.412357: update_curr_rt <-pick_next_task_rt
 irq/141-iwlwifi-640   [005] d... 132340.412358: pick_next_task_fair <-__schedule
 irq/141-iwlwifi-640   [005] d... 132340.412358: __msecs_to_jiffies <-pick_next_task_fair
 irq/141-iwlwifi-640   [005] d... 132340.412358: pick_next_task_idle <-__schedule
 irq/141-iwlwifi-640   [005] d... 132340.412358: put_prev_task_rt <-pick_next_task_idle
 irq/141-iwlwifi-640   [005] d... 132340.412358: update_curr_rt <-put_prev_task_rt
 irq/141-iwlwifi-640   [005] d... 132340.412358: update_rt_rq_load_avg <-put_prev_task_rt
 irq/141-iwlwifi-640   [005] d... 132340.412358: __update_idle_core <-pick_next_task_idle
 irq/141-iwlwifi-640   [005] d... 132340.412358: sched_switch: prev_comm=irq/141-iwlwifi prev_pid=640 prev_prio=49 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
 irq/141-iwlwifi-640   [005] d... 132340.412358: enter_lazy_tlb <-__schedule
          <idle>-0     [005] d... 132340.412359: finish_task_switch <-__schedule
          <idle>-0     [005] .... 132340.412359: do_idle <-cpu_startup_entry
          <idle>-0     [005] .... 132340.412359: tick_nohz_idle_enter <-do_idle
          <idle>-0     [005] d... 132340.412359: ktime_get <-tick_nohz_idle_enter
          <idle>-0     [005] d... 132340.412359: arch_cpu_idle_enter <-do_idle
          <idle>-0     [005] d... 132340.412359: tsc_verify_tsc_adjust <-arch_cpu_idle_enter
          <idle>-0     [005] d... 132340.412359: local_touch_nmi <-arch_cpu_idle_enter
          <idle>-0     [005] d... 132340.412359: tick_check_broadcast_expired <-do_idle
          <idle>-0     [005] d... 132340.412359: cpuidle_get_cpu_driver <-do_idle
          <idle>-0     [005] d... 132340.412359: cpuidle_not_available <-do_idle
          <idle>-0     [005] d... 132340.412360: cpuidle_select <-do_idle
          <idle>-0     [005] d... 132340.412360: menu_select <-cpuidle_select
          <idle>-0     [005] d... 132340.412360: cpuidle_governor_latency_req <-menu_select
          <idle>-0     [005] d... 132340.412360: pm_qos_request <-cpuidle_governor_latency_req
          <idle>-0     [005] d... 132340.412360: get_cpu_device <-cpuidle_governor_latency_req
          <idle>-0     [005] d... 132340.412360: pm_qos_read_value <-cpuidle_governor_latency_req
          <idle>-0     [005] d... 132340.412360: tick_nohz_get_sleep_length <-menu_select
          <idle>-0     [005] d... 132340.412360: can_stop_idle_tick.isra.14 <-tick_nohz_get_sleep_length
          <idle>-0     [005] d... 132340.412360: tick_nohz_next_event <-tick_nohz_get_sleep_length
          <idle>-0     [005] d... 132340.412360: rcu_needs_cpu <-tick_nohz_next_event
          <idle>-0     [005] d... 132340.412360: get_next_timer_interrupt <-tick_nohz_next_event
          <idle>-0     [005] d... 132340.412361: _raw_spin_lock <-get_next_timer_interrupt
          <idle>-0     [005] d... 132340.412361: __next_timer_interrupt <-get_next_timer_interrupt
          <idle>-0     [005] d... 132340.412361: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [005] d... 132340.412361: _raw_spin_lock_irqsave <-hrtimer_get_next_event
          <idle>-0     [005] d... 132340.412361: _raw_spin_unlock_irqrestore <-hrtimer_get_next_event
          <idle>-0     [005] d... 132340.412361: timekeeping_max_deferment <-tick_nohz_next_event
          <idle>-0     [005] d... 132340.412361: hrtimer_next_event_without <-tick_nohz_get_sleep_length
          <idle>-0     [005] d... 132340.412361: _raw_spin_lock_irqsave <-hrtimer_next_event_without
          <idle>-0     [005] d... 132340.412361: __hrtimer_next_event_base <-hrtimer_next_event_without
          <idle>-0     [005] d... 132340.412362: __hrtimer_next_event_base <-hrtimer_next_event_without
          <idle>-0     [005] d... 132340.412362: _raw_spin_unlock_irqrestore <-hrtimer_next_event_without
          <idle>-0     [005] d... 132340.412362: nr_iowait_cpu <-menu_select
          <idle>-0     [005] d... 132340.412362: tick_nohz_tick_stopped <-menu_select
          <idle>-0     [005] d... 132340.412362: tick_nohz_idle_stop_tick <-do_idle
          <idle>-0     [005] d... 132340.412362: calc_load_nohz_start <-tick_nohz_idle_stop_tick
          <idle>-0     [005] d... 132340.412362: quiet_vmstat <-tick_nohz_idle_stop_tick
          <idle>-0     [005] d... 132340.412362: need_update <-quiet_vmstat
          <idle>-0     [005] d... 132340.412363: first_online_pgdat <-need_update
          <idle>-0     [005] d... 132340.412363: next_zone <-need_update
          <idle>-0     [005] d... 132340.412363: next_zone <-need_update
          <idle>-0     [005] d... 132340.412363: next_zone <-need_update
          <idle>-0     [005] d... 132340.412363: next_zone <-need_update
          <idle>-0     [005] d... 132340.412363: next_zone <-need_update
          <idle>-0     [005] d... 132340.412363: next_online_pgdat <-next_zone
          <idle>-0     [005] d... 132340.412363: tick_stop: success=1 dependency=NONE
          <idle>-0     [005] d... 132340.412363: hrtimer_start_range_ns <-tick_nohz_idle_stop_tick
          <idle>-0     [005] d... 132340.412364: lock_hrtimer_base.isra.21 <-hrtimer_start_range_ns
          <idle>-0     [005] d... 132340.412364: _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.21

Cascone, K. (2000). The aesthetics of failure:“Post-digital” tendencies in contemporary computer music. Computer Music Journal, 24(4), 12-18.

           sleep-2639  [004] .... 132340.896001: unlock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896001: __unlock_page_memcg <-unlock_page_memcg
           sleep-2639  [004] .... 132340.896001: __tlb_remove_page_size <-unmap_page_range
           sleep-2639  [004] .... 132340.896001: vm_normal_page <-unmap_page_range
           sleep-2639  [004] .... 132340.896001: mark_page_accessed <-unmap_page_range
           sleep-2639  [004] .... 132340.896001: page_remove_rmap <-unmap_page_range
           sleep-2639  [004] .... 132340.896001: lock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896001: PageHuge <-page_remove_rmap
           sleep-2639  [004] .... 132340.896001: unlock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: __unlock_page_memcg <-unlock_page_memcg
           sleep-2639  [004] .... 132340.896002: __tlb_remove_page_size <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: vm_normal_page <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: mark_page_accessed <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: page_remove_rmap <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: lock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: PageHuge <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: unlock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: __unlock_page_memcg <-unlock_page_memcg
           sleep-2639  [004] .... 132340.896002: __tlb_remove_page_size <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: vm_normal_page <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: mark_page_accessed <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: page_remove_rmap <-unmap_page_range
           sleep-2639  [004] .... 132340.896002: lock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: PageHuge <-page_remove_rmap
           sleep-2639  [004] .... 132340.896002: unlock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896003: __unlock_page_memcg <-unlock_page_memcg
           sleep-2639  [004] .... 132340.896003: __tlb_remove_page_size <-unmap_page_range
           sleep-2639  [004] .... 132340.896003: vm_normal_page <-unmap_page_range
           sleep-2639  [004] .... 132340.896003: mark_page_accessed <-unmap_page_range
           sleep-2639  [004] .... 132340.896003: page_remove_rmap <-unmap_page_range
           sleep-2639  [004] .... 132340.896003: lock_page_memcg <-page_remove_rmap
           sleep-2639  [004] .... 132340.896003: PageHuge <-page_remove_rmap
           sleep-2639  [004] .... 132340.896003: unlock_page_memcg <-page_remove_rmap

16.9 MiB of text, that is around 17.7 million characters, describing a second of nothing happening.

[ . . . ]

[ . . . ]

[ . . . ]

[ . . . ]

[ . . . ]