modernize examples/plugin_log_task_usage to cgroup v2

examples/plugin_log_task_usage/StressTest.wdl

@@ -0,0 +1,31 @@
+version 1.1
+# MINIWDL__LOG_TASK_USAGE__PERIOD=2 miniwdl run examples/plugin_log_task_usage/StressTest.wdl --dir /tmp --verbose
+
+task StressTest {
+    input {
+        Int cpu = 4
+        Int memory_G = 2
+        Int cpu_memory_duration_s = 10
+        Int disk_load_G = 4
+
+        String docker = "polinux/stress" # Docker image with stress tool
+    }
+
+    command <<<
+        set -euxo pipefail
+
+        stress --cpu 4 --vm 1 --vm-bytes ~{memory_G}G --vm-hang 0 --timeout ~{cpu_memory_duration_s}s || true
+        dd if=/dev/zero of=testfile bs=1G count=~{disk_load_G}
+        sync
+        cat testfile > /dev/null &
+        sleep 5
+    >>>
+
+    runtime {
+        docker: docker
+        memory: "${memory_G*2}G"
+        cpu: cpu
+    }
+
+    output {}
+}

examples/plugin_log_task_usage/miniwdl_log_task_usage.py

@@ -7,8 +7,8 @@
 set configuration [log_task_usage] period (or the environment variable
 MINIWDL__LOG_TASK_USAGE__PERIOD) to the desired logging period in seconds.
 
-YMMV because host OS version & configuration may affect availability of the counters read from
-pseudo-files under /sys/fs/cgroup
+YMMV because host OS version & configuration may affect availability of the cgroup v2 counters read
+from pseudo-files under /sys/fs/cgroup
 """
 
 import WDL
@@ -21,42 +21,78 @@ def main(cfg, logger, run_id, run_dir, task, **recv):
     # inject logger into command script
     if cfg.has_option("log_task_usage", "period"):
         period = cfg["log_task_usage"].get_int("period")
-        recv["command"] = _logger_sh + f"log_cpu_mem_in_docker {period} &\n\n" + recv["command"]
+        recv["command"] = _logger_sh + f"_miniwdl_log_task_usage {period} &\n\n" + recv["command"]
     recv = yield recv
 
     # do nothing with outputs
     yield recv
 
 
 _logger_sh = r"""
-log_cpu_mem_in_docker() {
+_miniwdl_log_task_usage() {
     set +ex
     PERIOD_SECS=${1:-10}  # logging period (default 10s)
-    JIFFIES_PER_SEC=100   # see http://man7.org/linux/man-pages/man7/time.7.html
-    T_0=$(date +%s)
+    if [ ! -f /sys/fs/cgroup/cpu.stat ] || [ ! -f /sys/fs/cgroup/io.stat ]; then
+        >&2 echo "miniwdl_log_task_usage unable to report: cgroup v2 counters /sys/fs/cgroup/{cpu,io}.stat not found"
+        exit 1
+    fi
+
+    # CPU usage in microseconds
+    cpu_usecs() {
+        awk '/^usage_usec/ {print $2}' /sys/fs/cgroup/cpu.stat
+    }
 
-    cpu_user_jiffies() {
-        cut -f2 -d ' ' /sys/fs/cgroup/cpuacct/cpuacct.stat | head -n 1
+    # total block device I/O
+    io_bytes() {
+        awk '{
+            for (i = 1; i <= NF; i++) {
+                if ($i ~ /^rbytes=/) {
+                    rbytes += substr($i, index($i, "=") + 1);
+                }
+                if ($i ~ /^wbytes=/) {
+                    wbytes += substr($i, index($i, "=") + 1);
+                }
+            }
+        }
+        END {
+            print rbytes, wbytes;
+        }' /sys/fs/cgroup/io.stat
     }
-    user_jiffies_0=$(cpu_user_jiffies)
-    user_jffies_last=$user_jiffies_0
+
+    T_0=$(date +%s)
+    cpu_usecs_0=$(cpu_usecs)
+    read rbytes0 wbytes0 < <(io_bytes)
+    cpu_usecs_last=$cpu_usecs_0
+    rbytes_last=$rbytes0
+    wbytes_last=$wbytes0
     t_last=$T_0
+    mem_max_bytes=0
 
     while true; do
         sleep "$PERIOD_SECS"
         t=$(date +%s)
         wall_secs=$(( t - T_0 ))
 
-        user_jiffies=$(cpu_user_jiffies)
-        user_pct=$(( 100*(user_jiffies - user_jffies_last)/JIFFIES_PER_SEC/(t - t_last) ))
-        user_secs=$(( (user_jiffies - user_jiffies_0)/ JIFFIES_PER_SEC ))
+        cpu_usecs_current=$(cpu_usecs)
+        cpu_total_usecs=$(( cpu_usecs_current - cpu_usecs_0 ))
+        cpu_period_usecs=$(( cpu_usecs_current - cpu_usecs_last ))
 
-        user_jffies_last=$user_jiffies
-        t_last=$t
+        read rbytes_current wbytes_current < <(io_bytes)
+        rbytes_total=$(( rbytes_current - rbytes0 ))
+        wbytes_total=$(( wbytes_current - wbytes0 ))
+        rbytes_period=$(( rbytes_current - rbytes_last ))
+        wbytes_period=$(( wbytes_current - wbytes_last ))
 
-        rss_bytes=$(awk -F ' ' '$1 == "total_rss" { print $2 }'  /sys/fs/cgroup/memory/memory.stat)
+        mem_bytes=$(awk '$1 == "anon" { print $2 }' /sys/fs/cgroup/memory.stat)
+        mem_max_bytes=$(( mem_bytes > mem_max_bytes ? mem_bytes : mem_max_bytes ))
 
-        >&2 echo "container usage :: cpu_pct: ${user_pct}, mem_MiB: $(( rss_bytes/1048576 )), cpu_total_s: ${user_secs}, elapsed_s: ${wall_secs}"
+        >&2 echo "container usage (last ${PERIOD_SECS}s) :: cpu_pct: $(( 100 * cpu_period_usecs / 1000000 / PERIOD_SECS )), mem_GiB: $(( mem_bytes/1073741824 )), io_read_MiB: $(( rbytes_period/1048576 )), io_write_MiB: $(( wbytes_period/1048576 ))"
+        >&2 echo "container usage (total ${wall_secs}s) :: cpu_s: $(( cpu_total_usecs / 1000000 )), mem_max_GiB: $(( mem_max_bytes/1073741824 )), io_read_GiB: $(( rbytes_total/1073741824 )), io_write_GiB: $(( wbytes_total/1073741824 ))"
+
+        cpu_usecs_last=$cpu_usecs_current
+        rbytes_last=$rbytes_current
+        wbytes_last=$wbytes_current
+        t_last=$t
     done
 }
 """

examples/plugin_log_task_usage/setup.py

@@ -2,12 +2,13 @@
 
 setup(
     name='miniwdl_log_task_usage',
-    version='0.0.1',
-    description='miniwdl task plugin to log container cpu+mem usage',
+    version='0.1.0',
+    description='miniwdl task plugin to log container cpu/mem/io usage',
     author='Wid L. Hacker',
     py_modules=["miniwdl_log_task_usage"],
     python_requires='>=3.6',
     setup_requires=['reentry'],
+    install_requires=['miniwdl'],
     reentry_register=True,
     entry_points={
         'miniwdl.plugin.task': ['log_task_usage = miniwdl_log_task_usage:main'],