search

kata-containers / tests

Kata Containers tests, CI, and metrics
https://katacontainers.io/
Apache License 2.0
140 stars 196 forks source link

launch_times.sh scritp launch_times.sh: line 64: printf: %-s: invalid number #2488

Closed mdchao2010 closed 4 years ago

mdchao2010 commented 4 years ago

Description of problem

launch_times.sh: line 64: printf: %-s: invalid number

souce code

        declare workload_result
    readarray -n 0 workload_result < <(docker run --cap-add SYSLOG --rm --runtime=${RUNTIME} ${NETWORK_OPTION} ${IMAGE} sh -c "$DATECMD $DMESGCMD")

    end_time=$($DATECMD)

    # Delay this calculation until after we have run - do not want
    # to measure it in the results
    start_time=$(sn_to_ns $start_time)
    end_time=$(sn_to_ns $end_time)

    # Extract the 'date' info from the first line of the log
    # This script assumes the VM clock is in sync with the host clock...
    workload_time=${workload_result[0]}
    workload_time=$(echo $workload_time | tr -d '\r')
    workload_time=$(sn_to_ns $workload_time)

${workload_result[0]} is %-s:%-N,so when run sn_to_ns $workload_time faild

Expected result

(replace this text with an explanation of what you thought would happen)

Actual result

(replace this text with details of what actually happened)

jodh-intel commented 4 years ago

Thanks for raising @mdchao2010. This looks odd - fwics that scenario can only happen if there is no date(1) in your container? The default image is busybox so presumably you are using a different one?

Assigning to @grahamwhaley.

mdchao2010 commented 4 years ago

@jodh-intel default image is busybox, and there is date(1) in my container.

[root@ks-0 time]# docker  exec -it eb38f687c947 sh
/ # date
Tue Apr 28 16:32:15 UTC 2020
/ #

workload_result array is:

%-s:%-N
[ 0.000000] Linux version 4.19.86-8.1.container (katabuilduser@katabuildhost) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-39) (GCC)) #1 SMP Thu Jan 1 00:00:00 UTC 1970
[ 0.000000] Command line: tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro ro rootfstype=ext4 quiet systemd.show_status=false panic=1 nr_cpus=8 agent.use_vsock=false systemd.unit=kata-containers.target systemd.mask=systemd-networkd.service systemd.mask=systemd-networkd.socket
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: xstate_offset[3]: 960, xstate_sizes[3]: 64
[ 0.000000] x86/fpu: xstate_offset[4]: 1024, xstate_sizes[4]: 64
[ 0.000000] x86/fpu: xstate_offset[5]: 1088, xstate_sizes[5]: 64
[ 0.000000] x86/fpu: xstate_offset[6]: 1152, xstate_sizes[6]: 512
[ 0.000000] x86/fpu: xstate_offset[7]: 1664, xstate_sizes[7]: 1024
[ 0.000000] x86/fpu: xstate_offset[9]: 2688, xstate_sizes[9]: 8
[ 0.000000] x86/fpu: Enabled xstate features 0x2ff, context size is 2696 bytes, using 'standard' format.
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffdefff] usable
[ 0.000000] BIOS-e820: [mem 0x000000007ffdf000-0x000000007fffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.8 present.
[ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[ 0.000000] Hypervisor detected: KVM
[ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[ 0.000001] kvm-clock: cpu 0, msr 1fc6001, primary cpu clock
[ 0.000001] kvm-clock: using sched offset of 337542778 cycles
[ 0.000021] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[ 0.000073] tsc: Detected 2000.000 MHz processor
[ 0.001551] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.001555] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.001561] last_pfn = 0x7ffdf max_arch_pfn = 0x400000000
[ 0.001835] MTRR default type: write-back
[ 0.001836] MTRR fixed ranges enabled:
[ 0.001838] 00000-9FFFF write-back
[ 0.001839] A0000-BFFFF uncachable
[ 0.001840] C0000-FFFFF write-protect
[ 0.001841] MTRR variable ranges enabled:
[ 0.001843] 0 base 0080000000 mask FF80000000 uncachable
[ 0.001844] 1 disabled
[ 0.001844] 2 disabled
[ 0.001845] 3 disabled
[ 0.001846] 4 disabled
[ 0.001846] 5 disabled
[ 0.001847] 6 disabled
[ 0.001847] 7 disabled
[ 0.001957] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
[ 0.013476] found SMP MP-table at [mem 0x000f5a50-0x000f5a5f]
[ 0.013769] BRK [0x02201000, 0x02201fff] PGTABLE
[ 0.013773] BRK [0x02202000, 0x02202fff] PGTABLE
[ 0.013774] BRK [0x02203000, 0x02203fff] PGTABLE
[ 0.013857] BRK [0x02204000, 0x02204fff] PGTABLE
[ 0.014037] BRK [0x02205000, 0x02205fff] PGTABLE
[ 0.014197] ACPI: Early table checksum verification disabled
[ 0.014415] ACPI: RSDP 0x00000000000F5870 000014 (v00 BOCHS )
[ 0.014476] ACPI: RSDT 0x000000007FFE1DC2 00003C (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
[ 0.014539] ACPI: FACP 0x000000007FFE16A9 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
[ 0.014548] ACPI: DSDT 0x000000007FFDF040 002669 (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001)
[ 0.014553] ACPI: FACS 0x000000007FFDF000 000040
[ 0.014558] ACPI: APIC 0x000000007FFE171D 0000B0 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
[ 0.014563] ACPI: HPET 0x000000007FFE17CD 000038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001)
[ 0.014568] ACPI: SRAT 0x000000007FFE1805 000150 (v01 BOCHS BXPCSRAT 00000001 BXPC 00000001)
[ 0.014573] ACPI: SSDT 0x000000007FFE1955 00038D (v01 BOCHS NVDIMM 00000001 BXPC 00000001)
[ 0.014579] ACPI: NFIT 0x000000007FFE1CE2 0000E0 (v01 BOCHS BXPCNFIT 00000001 BXPC 00000001)
[ 0.014626] ACPI: Local APIC address 0xfee00000
[ 0.015586] Zone ranges:
[ 0.015587] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.015590] DMA32 [mem 0x0000000001000000-0x000000007ffdefff]
[ 0.015591] Normal empty
[ 0.015593] Device empty
[ 0.015594] Movable zone start for each node
[ 0.015595] Early memory node ranges
[ 0.015596] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.015597] node 0: [mem 0x0000000000100000-0x000000007ffdefff]
[ 0.015925] Reserved but unavailable: 98 pages
[ 0.015927] Initmem setup node 0 [mem 0x0000000000001000-0x000000007ffdefff]
[ 0.015929] On node 0 totalpages: 524157
[ 0.015950] DMA zone: 64 pages used for memmap
[ 0.015950] DMA zone: 21 pages reserved
[ 0.015952] DMA zone: 3998 pages, LIFO batch:0
[ 0.016147] DMA32 zone: 8128 pages used for memmap
[ 0.016148] DMA32 zone: 520159 pages, LIFO batch:63
[ 0.037510] ACPI: PM-Timer IO Port: 0x608
[ 0.037515] ACPI: Local APIC address 0xfee00000
[ 0.037549] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[ 0.037708] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[ 0.037712] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.037714] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[ 0.037715] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.037736] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[ 0.037737] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[ 0.037738] ACPI: IRQ0 used by override.
[ 0.037739] ACPI: IRQ5 used by override.
[ 0.037740] ACPI: IRQ9 used by override.
[ 0.037741] ACPI: IRQ10 used by override.
[ 0.037741] ACPI: IRQ11 used by override.
[ 0.037744] Using ACPI (MADT) for SMP configuration information
[ 0.037745] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[ 0.037760] smpboot: Allowing 8 CPUs, 7 hotplug CPUs
[ 0.037818] [mem 0x80000000-0xfeffbfff] available for PCI devices
[ 0.037818] Booting paravirtualized kernel on KVM
[ 0.037820] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[ 0.102283] random: get_random_bytes called from start_kernel+0x87/0x47e with crng_init=0
[ 0.102319] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:8 nr_node_ids:1
[ 0.103158] percpu: Embedded 39 pages/cpu s127384 r0 d32360 u262144
[ 0.103184] pcpu-alloc: s127384 r0 d32360 u262144 alloc=1*2097152
[ 0.103185] pcpu-alloc: [0] 0 1 2 3 4 5 6 7
[ 0.103261] KVM setup async PF for cpu 0
[ 0.103275] kvm-stealtime: cpu 0, msr 7da14e40
[ 0.103300] Built 1 zonelists, mobility grouping on. Total pages: 515944
[ 0.103302] Kernel command line: tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro ro rootfstype=ext4 quiet systemd.show_status=false panic=1 nr_cpus=8 agent.use_vsock=false systemd.unit=kata-containers.target systemd.mask=systemd-networkd.service systemd.mask=systemd-networkd.socket
[ 0.104705] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[ 0.104945] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[ 0.110164] Memory: 2040792K/2096628K available (8200K kernel code, 476K rwdata, 1212K rodata, 868K init, 2352K bss, 55836K reserved, 0K cma-reserved)
[ 0.110595] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[ 0.110601] Kernel/User page tables isolation: enabled
[ 0.111391] rcu: Hierarchical RCU implementation.
[ 0.111392] rcu: RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=8.
[ 0.111393] All grace periods are expedited (rcu_expedited).
[ 0.111394] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=8
[ 0.111475] NR_IRQS: 4352, nr_irqs: 488, preallocated irqs: 16
[ 0.111794] rcu: Offload RCU callbacks from CPUs: (none).
[ 0.112401] Console: colour *CGA 80x25
[ 0.112455] ACPI: Core revision 20180810
[ 0.113070] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[ 0.113377] hpet clockevent registered
[ 0.113435] APIC: Switch to symmetric I/O mode setup
[ 0.114456] x2apic enabled
[ 0.115370] Switched APIC routing to physical x2apic.
[ 0.119238] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.119317] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x39a85c9bff6, max_idle_ns: 881590591483 ns
[ 0.119319] Calibrating delay loop (skipped) preset value.. 4000.00 BogoMIPS (lpj=8000000)
[ 0.119322] pid_max: default: 32768 minimum: 301
[ 0.119398] Security Framework initialized
[ 0.119416] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.119421] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.120656] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[ 0.120657] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[ 0.120670] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[ 0.120674] Spectre V2 : Mitigation: Full generic retpoline
[ 0.120674] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 0.120675] Speculative Store Bypass: Vulnerable
[ 0.120676] MDS: Vulnerable: Clear CPU buffers attempted, no microcode
[ 0.120677] TAA: Vulnerable: Clear CPU buffers attempted, no microcode
[ 0.123750] Freeing SMP alternatives memory: 28K
[ 0.126963] TSC deadline timer enabled
[ 0.127007] smpboot: CPU0: Intel(R) Xeon(R) Gold 5117 CPU @ 2.00GHz (family: 0x6, model: 0x55, stepping: 0x4)
[ 0.127148] Performance Events: unsupported p6 CPU model 85 no PMU driver, software events only.
[ 0.127319] rcu: Hierarchical SRCU implementation.
[ 0.127319] smp: Bringing up secondary CPUs ...
[ 0.127319] smp: Brought up 1 node, 1 CPU
[ 0.127319] smpboot: Max logical packages: 8
[ 0.127319] smpboot: Total of 1 processors activated (4000.00 BogoMIPS)
[ 0.127319] devtmpfs: initialized
[ 0.127319] x86/mm: Memory block size: 128MB
[ 0.127319] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[ 0.127319] futex hash table entries: 2048 (order: 5, 131072 bytes)
[ 0.127319] NET: Registered protocol family 16
[ 0.127319] cpuidle: using governor menu
[ 0.127319] ACPI: bus type PCI registered
[ 0.127319] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 0.127319] PCI: Using configuration type 1 for base access
[ 0.127319] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 0.127319] ACPI: Added _OSI(Module Device)
[ 0.127319] ACPI: Added _OSI(Processor Device)
[ 0.127319] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.127319] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.127319] ACPI: Added _OSI(Linux-Dell-Video)
[ 0.127319] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[ 0.127948] ACPI: 2 ACPI AML tables successfully acquired and loaded
[ 0.130140] ACPI: Interpreter enabled
[ 0.130146] ACPI: (supports S0 S5)
[ 0.130147] ACPI: Using IOAPIC for interrupt routing
[ 0.130159] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 0.130447] ACPI: Enabled 4 GPEs in block 00 to 0F
[ 0.137619] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.137635] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[ 0.137640] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[ 0.138169] acpiphp: Slot [3] registered
[ 0.138267] acpiphp: Slot [4] registered
[ 0.138364] acpiphp: Slot [5] registered
[ 0.138473] acpiphp: Slot [6] registered
[ 0.138570] acpiphp: Slot [7] registered
[ 0.138666] acpiphp: Slot [8] registered
[ 0.138764] acpiphp: Slot [9] registered
[ 0.138880] acpiphp: Slot [10] registered
[ 0.138979] acpiphp: Slot [11] registered
[ 0.139075] acpiphp: Slot [12] registered
[ 0.139171] acpiphp: Slot [13] registered
[ 0.139266] acpiphp: Slot [14] registered
[ 0.139364] acpiphp: Slot [15] registered
[ 0.139473] acpiphp: Slot [16] registered
[ 0.139569] acpiphp: Slot [17] registered
[ 0.139665] acpiphp: Slot [18] registered
[ 0.139776] acpiphp: Slot [19] registered
[ 0.139874] acpiphp: Slot [20] registered
[ 0.139971] acpiphp: Slot [21] registered
[ 0.140067] acpiphp: Slot [22] registered
[ 0.140163] acpiphp: Slot [23] registered
[ 0.140259] acpiphp: Slot [24] registered
[ 0.140354] acpiphp: Slot [25] registered
[ 0.140464] acpiphp: Slot [26] registered
[ 0.140560] acpiphp: Slot [27] registered
[ 0.140655] acpiphp: Slot [28] registered
[ 0.140751] acpiphp: Slot [29] registered
[ 0.140846] acpiphp: Slot [30] registered
[ 0.140942] acpiphp: Slot [31] registered
[ 0.140975] PCI host bridge to bus 0000:00
[ 0.140978] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 0.140980] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 0.140981] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 0.140983] pci_bus 0000:00: root bus resource [mem 0x80000000-0xfebfffff window]
[ 0.140984] pci_bus 0000:00: root bus resource [mem 0x540000000-0x5bfffffff window]
[ 0.140986] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.141123] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 0.142608] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 0.144609] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[ 0.149023] pci 0000:00:01.1: reg 0x20: [io 0xd0e0-0xd0ef]
[ 0.151361] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 0.151363] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 0.151364] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 0.151365] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 0.151819] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[ 0.153509] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
[ 0.153540] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
[ 0.154334] pci 0000:00:02.0: [1b36:0001] type 01 class 0x060400
[ 0.156763] pci 0000:00:02.0: reg 0x10: [mem 0xfe600000-0xfe6000ff 64bit]
[ 0.159707] pci 0000:00:03.0: [1af4:1003] type 00 class 0x078000
[ 0.162237] pci 0000:00:03.0: reg 0x10: [io 0xd000-0xd03f]
[ 0.163332] pci 0000:00:03.0: reg 0x14: [mem 0xfe601000-0xfe601fff]
[ 0.171330] pci 0000:00:04.0: [1af4:1004] type 00 class 0x010000
[ 0.173897] pci 0000:00:04.0: reg 0x10: [io 0xd040-0xd07f]
[ 0.174901] pci 0000:00:04.0: reg 0x14: [mem 0xfe602000-0xfe602fff]
[ 0.180871] pci 0000:00:05.0: [1af4:1005] type 00 class 0x00ff00
[ 0.182645] pci 0000:00:05.0: reg 0x10: [io 0xd0c0-0xd0df]
[ 0.187061] pci 0000:00:05.0: reg 0x20: [mem 0xfea00000-0xfea03fff 64bit pref]
[ 0.189583] pci 0000:00:06.0: [1af4:1009] type 00 class 0x000200
[ 0.190807] pci 0000:00:06.0: reg 0x10: [io 0xd080-0xd0bf]
[ 0.191836] pci 0000:00:06.0: reg 0x14: [mem 0xfe603000-0xfe603fff]
[ 0.201145] pci_bus 0000:01: extended config space not accessible
[ 0.201419] acpiphp: Slot [0] registered
[ 0.201505] acpiphp: Slot [1] registered
[ 0.201589] acpiphp: Slot [2] registered
[ 0.201679] acpiphp: Slot [3-2] registered
[ 0.201766] acpiphp: Slot [4-2] registered
[ 0.201854] acpiphp: Slot [5-2] registered
[ 0.201954] acpiphp: Slot [6-2] registered
[ 0.202043] acpiphp: Slot [7-2] registered
[ 0.202132] acpiphp: Slot [8-2] registered
[ 0.202220] acpiphp: Slot [9-2] registered
[ 0.202309] acpiphp: Slot [10-2] registered
[ 0.202399] acpiphp: Slot [11-2] registered
[ 0.202487] acpiphp: Slot [12-2] registered
[ 0.202575] acpiphp: Slot [13-2] registered
[ 0.202664] acpiphp: Slot [14-2] registered
[ 0.202752] acpiphp: Slot [15-2] registered
[ 0.202842] acpiphp: Slot [16-2] registered
[ 0.202930] acpiphp: Slot [17-2] registered
[ 0.203025] acpiphp: Slot [18-2] registered
[ 0.203113] acpiphp: Slot [19-2] registered
[ 0.203201] acpiphp: Slot [20-2] registered
[ 0.203296] acpiphp: Slot [21-2] registered
[ 0.203392] acpiphp: Slot [22-2] registered
[ 0.203483] acpiphp: Slot [23-2] registered
[ 0.203572] acpiphp: Slot [24-2] registered
[ 0.203662] acpiphp: Slot [25-2] registered
[ 0.203750] acpiphp: Slot [26-2] registered
[ 0.203838] acpiphp: Slot [27-2] registered
[ 0.203933] acpiphp: Slot [28-2] registered
[ 0.204022] acpiphp: Slot [29-2] registered
[ 0.204111] acpiphp: Slot [30-2] registered
[ 0.204200] acpiphp: Slot [31-2] registered
[ 0.205592] pci 0000:00:02.0: PCI bridge to [bus 01]
[ 0.205645] pci 0000:00:02.0: bridge window [io 0xc000-0xcfff]
[ 0.205697] pci 0000:00:02.0: bridge window [mem 0xfe400000-0xfe5fffff]
[ 0.205799] pci 0000:00:02.0: bridge window [mem 0xfe800000-0xfe9fffff 64bit pref]
[ 0.206710] pci_bus 0000:00: on NUMA node 0
[ 0.207197] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[ 0.207386] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[ 0.207545] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[ 0.207703] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[ 0.207787] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[ 0.208852] vgaarb: loaded
[ 0.208997] SCSI subsystem initialized
[ 0.209015] PCI: Using ACPI for IRQ routing
[ 0.209016] PCI: pci_cache_line_size set to 64 bytes
[ 0.209500] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 0.209502] e820: reserve RAM buffer [mem 0x7ffdf000-0x7fffffff]
[ 0.209917] clocksource: Switched to clocksource kvm-clock
[ 0.210062] pnp: PnP ACPI init
[ 0.210134] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[ 0.210156] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[ 0.210174] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[ 0.210183] pnp 00:03: [dma 2]
[ 0.210190] pnp 00:03: Plug and Play ACPI device, IDs PNP0700 (active)
[ 0.211058] pnp: PnP ACPI: found 4 devices
[ 0.214005] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 0.214789] pci 0000:00:02.0: PCI bridge to [bus 01]
[ 0.214820] pci 0000:00:02.0: bridge window [io 0xc000-0xcfff]
[ 0.215678] pci 0000:00:02.0: bridge window [mem 0xfe400000-0xfe5fffff]
[ 0.216229] pci 0000:00:02.0: bridge window [mem 0xfe800000-0xfe9fffff 64bit pref]
[ 0.217314] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 0.217316] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 0.217317] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 0.217319] pci_bus 0000:00: resource 7 [mem 0x80000000-0xfebfffff window]
[ 0.217320] pci_bus 0000:00: resource 8 [mem 0x540000000-0x5bfffffff window]
[ 0.217321] pci_bus 0000:01: resource 0 [io 0xc000-0xcfff]
[ 0.217323] pci_bus 0000:01: resource 1 [mem 0xfe400000-0xfe5fffff]
[ 0.217324] pci_bus 0000:01: resource 2 [mem 0xfe800000-0xfe9fffff 64bit pref]
[ 0.217444] NET: Registered protocol family 2
[ 0.217870] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes)
[ 0.217875] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[ 0.217894] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[ 0.217924] TCP: Hash tables configured (established 16384 bind 16384)
[ 0.218037] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[ 0.218043] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[ 0.218132] NET: Registered protocol family 1
[ 0.218217] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[ 0.218255] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.218284] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.218507] PCI: CLS 0 bytes, default 64
[ 0.218700] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x39a85c9bff6, max_idle_ns: 881590591483 ns
[ 0.218952] workingset: timestamp_bits=46 max_order=19 bucket_order=0
[ 0.220491] SGI XFS with security attributes, no debug enabled
[ 0.221255] 9p: Installing v9fs 9p2000 file system support
[ 0.221404] NET: Registered protocol family 38
[ 0.221421] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.221461] io scheduler noop registered (default)
[ 0.221754] shpchp 0000:00:02.0: Requesting control of SHPC hotplug via OSHP (\_SB_.PCI0.S10_)
[ 0.221758] shpchp 0000:00:02.0: Requesting control of SHPC hotplug via OSHP (\_SB_.PCI0)
[ 0.221761] shpchp 0000:00:02.0: Cannot get control of SHPC hotplug
[ 0.221766] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 0.221840] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 0.221853] ACPI: Power Button [PWRF]
[ 0.250633] PCI Interrupt Link [LNKC] enabled at IRQ 11
[ 0.250791] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
[ 0.275611] PCI Interrupt Link [LNKD] enabled at IRQ 10
[ 0.275749] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
[ 0.299835] PCI Interrupt Link [LNKA] enabled at IRQ 10
[ 0.325958] PCI Interrupt Link [LNKB] enabled at IRQ 11
[ 0.326093] virtio-pci 0000:00:06.0: virtio_pci: leaving for legacy driver
[ 0.326874] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[ 0.340939] console [hvc0] enabled
[ 0.342443] brd: module loaded
[ 0.343139] loop: module loaded
[ 0.345223] pmem0: p1
[ 0.345273] pmem0: detected capacity change from 0 to 132120576
[ 0.347495] scsi host0: Virtio SCSI HBA
[ 0.348069] random: fast init done
[ 0.348258] random: crng init done
[ 0.368456] xt_time: kernel timezone is -0000
[ 0.368497] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[ 0.368517] IPVS: Connection hash table configured (size=4096, memory=64Kbytes)
[ 0.368629] IPVS: ipvs loaded.
[ 0.368640] IPVS: [rr] scheduler registered.
[ 0.368640] IPVS: [wrr] scheduler registered.
[ 0.368641] IPVS: [lc] scheduler registered.
[ 0.368642] IPVS: [wlc] scheduler registered.
[ 0.368642] IPVS: [fo] scheduler registered.
[ 0.368643] IPVS: [ovf] scheduler registered.
[ 0.368655] IPVS: [lblc] scheduler registered.
[ 0.368657] IPVS: [lblcr] scheduler registered.
[ 0.368657] IPVS: [dh] scheduler registered.
[ 0.368658] IPVS: [sh] scheduler registered.
[ 0.368659] IPVS: [sed] scheduler registered.
[ 0.368659] IPVS: [nq] scheduler registered.
[ 0.368689] IPVS: ftp: loaded support on port[0] = 21
[ 0.368689] IPVS: [sip] pe registered.
[ 0.368880] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully
[ 0.368909] Initializing XFRM netlink socket
[ 0.369033] NET: Registered protocol family 10
[ 0.369506] Segment Routing with IPv6
[ 0.369579] NET: Registered protocol family 17
[ 0.369669] 9pnet: Installing 9P2000 support
[ 0.371026] NET: Registered protocol family 40
[ 0.371090] sched_clock: Marking stable (360320596, 7491741)->(374869482, -7057145)
[ 0.371775] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk
[ 0.372663] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro
[ 0.372670] VFS: Mounted root (ext4 filesystem) readonly on device 259:1.
[ 0.372727] devtmpfs: mounted
[ 0.375951] Freeing unused kernel image memory: 868K
[ 0.379389] Write protecting the kernel read-only data: 12288k
[ 0.384962] Freeing unused kernel image memory: 2024K
[ 0.385261] Freeing unused kernel image memory: 836K
[ 0.385283] Run /sbin/init as init process
[ 0.409002] systemd[1]: systemd 245 running in system mode. (+PAM +AUDIT -SELINUX +IMA -APPARMOR -SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[ 0.409029] systemd[1]: Detected virtualization kvm.
[ 0.409061] systemd[1]: Detected architecture x86-64.
[ 0.410636] systemd[1]: No hostname configured.
[ 0.410641] systemd[1]: Set hostname to <localhost>.
[ 0.410729] systemd[1]: Initializing machine ID from random generator.
[ 0.410768] systemd[1]: Installed transient /etc/machine-id file.
[ 0.447507] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ 0.447791] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 0.447807] systemd[1]: Reached target Local Encrypted Volumes.
[ 0.447818] systemd[1]: Reached target Paths.
[ 0.447826] systemd[1]: Reached target Slices.
[ 0.447988] systemd[1]: Listening on Process Core Dump Socket.
[ 0.448029] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 0.448037] systemd[1]: Reached target Sockets.
[ 0.448133] systemd[1]: Condition check resulted in Kernel Trace File System being skipped.
[ 0.448168] systemd[1]: Condition check resulted in Create list of static device nodes for the current kernel being skipped.
[ 0.448191] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[ 0.448326] systemd[1]: Condition check resulted in Load Kernel Modules being skipped.
[ 0.449367] systemd[1]: Starting Remount Root and Kernel File Systems...
[ 0.449996] systemd[1]: Starting Repartition Root Disk...
[ 0.450700] systemd[1]: Starting Apply Kernel Variables...
[ 0.453351] systemd[39]: systemd-repart.service: Failed to connect stdout to the journal socket, ignoring: No such file or directory
[ 0.453933] systemd[40]: systemd-sysctl.service: Failed to connect stdout to the journal socket, ignoring: No such file or directory
[ 0.454168] systemd[38]: systemd-remount-fs.service: Failed to connect stdout to the journal socket, ignoring: No such file or directory
[ 0.468464] systemd[1]: Finished Remount Root and Kernel File Systems.
[ 0.468643] systemd[1]: Reached target Local File Systems (Pre).
[ 0.468662] systemd[1]: Condition check resulted in Default Swap File (/var/swapfile) being skipped.
[ 0.468669] systemd[1]: Reached target Swap.
[ 0.469409] systemd[1]: Mounting Temporary Directory (/tmp)...
[ 0.469443] systemd[1]: Condition check resulted in Flush Journal to Persistent Storage being skipped.
[ 0.470107] systemd-sysctl[40]: Couldn't write '16' to 'kernel/sysrq', ignoring: No such file or directory
[ 0.471202] systemd[1]: Finished Repartition Root Disk.
[ 0.471541] systemd-sysctl[40]: Not setting net/ipv4/conf/all/rp_filter (explicit setting exists).
[ 0.471544] systemd-sysctl[40]: Not setting net/ipv4/conf/default/rp_filter (explicit setting exists).
[ 0.471579] systemd-sysctl[40]: Not setting net/ipv4/conf/all/accept_source_route (explicit setting exists).
[ 0.471581] systemd-sysctl[40]: Not setting net/ipv4/conf/default/accept_source_route (explicit setting exists).
[ 0.471610] systemd-sysctl[40]: Not setting net/ipv4/conf/all/promote_secondaries (explicit setting exists).
[ 0.471613] systemd-sysctl[40]: Not setting net/ipv4/conf/default/promote_secondaries (explicit setting exists).
[ 0.472257] systemd[1]: Finished Apply Kernel Variables.
[ 0.472965] systemd[41]: tmp.mount: Failed to connect stdout to the journal socket, ignoring: No such file or directory
[ 0.476707] systemd[1]: Mounted Temporary Directory (/tmp).
[ 0.476771] systemd[1]: Reached target Local File Systems.
[ 0.476793] systemd[1]: Condition check resulted in Store a System Token in an EFI Variable being skipped.
[ 0.476822] systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
[ 0.476830] systemd[1]: Reached target System Initialization.
[ 0.476898] systemd[1]: Started Daily Cleanup of Temporary Directories.
[ 0.476907] systemd[1]: Reached target Basic System.
[ 0.476944] systemd[1]: Reached target Timers.
[ 0.477014] systemd[1]: Condition check resulted in NTP client/server being skipped.
[ 0.477625] systemd[1]: Started Kata Containers Agent.
[ 0.477674] systemd[1]: Reached target Kata Containers Agent Target.
[ 0.477751] systemd[1]: Startup finished in 394ms (kernel) + 75ms (userspace) = 470ms.
[ 1.589865] pci 0000:00:02.0: PCI bridge to [bus 01]
[ 1.589901] pci 0000:00:02.0: bridge window [io 0xc000-0xcfff]
[ 1.591255] pci 0000:00:02.0: bridge window [mem 0xfe400000-0xfe5fffff]
[ 1.592218] pci 0000:00:02.0: bridge window [mem 0xfe800000-0xfe9fffff 64bit pref]
[ 1.621188] systemd[1]: run-libcontainer-e71c7b80cf8238ecd3fecda563e5f88922148da9e280146e01e79663815f4e26-e71c7b80cf8238ecd3fecda563e5f88922148da9e280146e01e79663815f4e26-runc.7FjXPh.mount: Succeeded.

when print workload_result array, code is success. This is so weird.

This is result :

"boot-times-scaling-nonet" : {
        "Results": [
                        {
                "total": {
                        "Result": 1.824,
                        "Units" : "s"
                },
                "to-workload": {
                        "Result": -1588090571.362,
                        "Units" : "s"
                },
                "in-kernel": {
                        "Result": 0.403144,
                        "Units" : "s"
                },
                "to-kernel": {
                        "Result": -1588090571.765144,
                        "Units" : "s"
                },
                "to-quit": {
                        "Result": 1588090573.186,
                        "Units" : "s"
                }
        }
        ]
        }
grahamwhaley commented 4 years ago

Hi @mdchao2010 . The date command in busybox cannot print out the correct format needed by the test - it is a limitation of the cut down busybox date command. See the comments in the test script:

# Note, the <image> used for this test must support the full 'date' command
# syntax - the date from busybox for instance *does not* support this, so
# will not work with this test.

You can see an example ubuntu invocation in the report generator script as an example:

    # Run the time tests - take time measures for an ubuntu image, over
    # 100 'first and only container' launches.
    # NOTE - whichever container you test here must support a full 'date'
    # command - busybox based containers (including Alpine) will not work.
    bash time/launch_times.sh -i ubuntu -n 100

Yes, the script could try to catch this problem more cleanly, and we could/should document the fact more visibly as well!

ariel-adam commented 4 years ago

The relevant information has been added to the script so we are closing this issue:

https://github.com/kata-containers/tests/blob/master/metrics/time/launch_times.sh#L16-L18