diff --git a/performance/performance_evaluation.py b/performance/performance_evaluation.py index cf9933b..045c6fd 100644 --- a/performance/performance_evaluation.py +++ b/performance/performance_evaluation.py @@ -15,8 +15,9 @@ MEASUREMENT_REGEX = r"^.* " + MEASUREMENT_TAG + r" ([a-zA-Z_:-]*) ([0-9]*)$" # TODO change this for the actual measurement # data_basedir = os.environ.get("BFBUILD_QEMU") -data_basedir = os.environ.get("BFBUILD") -data_file = os.path.join(data_basedir, "full_output.log") +# data_basedir = os.environ.get("BFBUILD") +data_basedir = "./plots" +# data_file = os.path.join(data_basedir, "full_output.log") out_dir = os.path.join(os.path.dirname(sys.argv[0]), "plots") def extract_measurement(line): @@ -58,30 +59,15 @@ def build_dataseries(measurements, start_tag, end_tag): return datapoints - -def main(): - raw_log = read_data(data_file) +def get_measurements_from_file(file): + raw_log = read_data(os.path.join(data_basedir, file)) measurements = extract_measurements(raw_log) measurements.sort(key=lambda m: m["timestamp"]) - dataset = {} - - # dataset["performance"] = build_dataseries(measurements, "aos_performance:start", "aos_performance:done") - - # URPC - # dataset["client_to_server"] = build_dataseries(measurements, "aos_urpc_nop:start", "aos_urpc_server:start") - # dataset["server_schedule_task"] = build_dataseries(measurements, "aos_urpc_server:start", "aos_urpc_server:triggered_closure") - # dataset["server_completed_task"] = build_dataseries(measurements, "aos_urpc_server:triggered_closure", "aos_urpc_server:done") - # dataset["server_to_client"] = build_dataseries(measurements, "aos_urpc_server:done", "aos_urpc_nop:done") - - # block driver - dataset["block_driver_read_device"] = build_dataseries(measurements, "block_driver_read_object:start", "block_driver_read_object:memcpy") - dataset["block_driver_read_memcpy"] = build_dataseries(measurements, "block_driver_read_object:memcpy", "block_driver_read_object:done") - dataset["block_driver_write_read"] = build_dataseries(measurements, "block_driver_write_object:start", "block_driver_write_object:read") - dataset["block_driver_write_memcpy"] = build_dataseries(measurements, "block_driver_write_object:read", "block_driver_write_object:memcpy") - dataset["block_driver_write_device"] = build_dataseries(measurements, "block_driver_write_object:memcpy", "block_driver_write_object:done") + return measurements +def create_bar_chart(dataset, title, out_file): # calculate stats for each data series metrics = {} for key in dataset: @@ -90,22 +76,10 @@ def main(): d_median = median(dataset[key]) metrics[key] = (d_mean, d_std) - # create output directory - os.makedirs(out_dir, exist_ok=True) - - # create plots for data series - for key in dataset: - d = dataset[key] - p.clf() - p.title(key) - p.xlabel("datapoint index") - p.ylabel("duration (cycles)") - p.plot(range(len(d)), d) - p.savefig(os.path.join(out_dir, f"{key}.jpg")) - + # create the plot p.clf() - fig, ax = p.subplots(figsize=(12,5)) - p.title("Metrics") + fig, ax = p.subplots() #figsize=(12,5)) + p.title(title) p.ylabel("median duration (cycles)") p.bar( metrics.keys(), @@ -113,7 +87,49 @@ def main(): yerr=[x[1] for x in metrics.values()], ) ax.set_ylim(0) - p.savefig(os.path.join(out_dir, "metrics.jpg")) + p.savefig(os.path.join(out_dir, out_file)) + +def main(): + + dataset = {} + + # dataset["performance"] = build_dataseries(measurements, "aos_performance:start", "aos_performance:done") + + # URPC + # title = "URPC Micro Benchmark" + # dataset["client_to_server"] = build_dataseries(measurements, "aos_urpc_nop:start", "aos_urpc_server:start") + # dataset["server_schedule_task"] = build_dataseries(measurements, "aos_urpc_server:start", "aos_urpc_server:triggered_closure") + # dataset["server_completed_task"] = build_dataseries(measurements, "aos_urpc_server:triggered_closure", "aos_urpc_server:done") + # dataset["server_to_client"] = build_dataseries(measurements, "aos_urpc_server:done", "aos_urpc_nop:done") + + # BLOCK DRIVER + # measurements = get_measurements_from_file("block_driver/no_optimization.log") + # dataset = {} + # # we skip the first datapoint here because it is reliably very high compared to all others + # dataset["read_device"] = build_dataseries(measurements, "block_driver_read_object:start", "block_driver_read_object:memcpy")[1:] + # dataset["read_memcpy"] = build_dataseries(measurements, "block_driver_read_object:memcpy", "block_driver_read_object:done") + # dataset["write_read"] = build_dataseries(measurements, "block_driver_write_object:start", "block_driver_write_object:read") + # dataset["write_memcpy"] = build_dataseries(measurements, "block_driver_write_object:read", "block_driver_write_object:memcpy") + # dataset["write_device"] = build_dataseries(measurements, "block_driver_write_object:memcpy", "block_driver_write_object:done") + # create_bar_chart(dataset, "Block Driver Micro Benchmark", "block_driver/no_optimization.jpg") + # measurements = get_measurements_from_file("block_driver/no_sleep.log") + # dataset_compare = {} + # dataset_compare["read_unopt"] = dataset["read_device"] + # dataset_compare["write_unopt"] = dataset["write_device"] + # dataset_compare["read_nosleep"] = build_dataseries(measurements, "block_driver_read_object:start", "block_driver_read_object:memcpy")[1:] + # dataset_compare["write_nosleep"] = build_dataseries(measurements, "block_driver_write_object:memcpy", "block_driver_write_object:done") + # create_bar_chart(dataset_compare, "Block Driver Optimizations", "block_driver/optimizations.jpg") + + # create plots for data series + # for key in dataset: + # d = dataset[key] + # p.clf() + # p.title(key) + # p.xlabel("datapoint index") + # p.ylabel("duration (cycles)") + # p.plot(range(len(d)), d) + # p.savefig(os.path.join(out_dir, f"{key}.jpg")) + if __name__ == "__main__": main() diff --git a/performance/plots/archive/block_driver_raw/block_driver_read_device.jpg b/performance/plots/archive/block_driver_raw/block_driver_read_device.jpg deleted file mode 100644 index 4dd4388..0000000 Binary files a/performance/plots/archive/block_driver_raw/block_driver_read_device.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/block_driver_read_memcpy.jpg b/performance/plots/archive/block_driver_raw/block_driver_read_memcpy.jpg deleted file mode 100644 index d519b37..0000000 Binary files a/performance/plots/archive/block_driver_raw/block_driver_read_memcpy.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/block_driver_write_device.jpg b/performance/plots/archive/block_driver_raw/block_driver_write_device.jpg deleted file mode 100644 index a377f03..0000000 Binary files a/performance/plots/archive/block_driver_raw/block_driver_write_device.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/block_driver_write_memcpy.jpg b/performance/plots/archive/block_driver_raw/block_driver_write_memcpy.jpg deleted file mode 100644 index 5600211..0000000 Binary files a/performance/plots/archive/block_driver_raw/block_driver_write_memcpy.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/block_driver_write_read.jpg b/performance/plots/archive/block_driver_raw/block_driver_write_read.jpg deleted file mode 100644 index 7d1a225..0000000 Binary files a/performance/plots/archive/block_driver_raw/block_driver_write_read.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/full_output.log b/performance/plots/archive/block_driver_raw/full_output.log deleted file mode 100644 index 17c4f30..0000000 Binary files a/performance/plots/archive/block_driver_raw/full_output.log and /dev/null differ diff --git a/performance/plots/archive/block_driver_raw/metrics.jpg b/performance/plots/archive/block_driver_raw/metrics.jpg deleted file mode 100644 index 8f29334..0000000 Binary files a/performance/plots/archive/block_driver_raw/metrics.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/block_driver_read_device.jpg b/performance/plots/archive/block_driver_single_chache/block_driver_read_device.jpg deleted file mode 100644 index 5c95940..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/block_driver_read_device.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/block_driver_read_memcpy.jpg b/performance/plots/archive/block_driver_single_chache/block_driver_read_memcpy.jpg deleted file mode 100644 index f81cfa7..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/block_driver_read_memcpy.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/block_driver_write_device.jpg b/performance/plots/archive/block_driver_single_chache/block_driver_write_device.jpg deleted file mode 100644 index 2e7ca56..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/block_driver_write_device.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/block_driver_write_memcpy.jpg b/performance/plots/archive/block_driver_single_chache/block_driver_write_memcpy.jpg deleted file mode 100644 index b531891..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/block_driver_write_memcpy.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/block_driver_write_read.jpg b/performance/plots/archive/block_driver_single_chache/block_driver_write_read.jpg deleted file mode 100644 index a7dc3fb..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/block_driver_write_read.jpg and /dev/null differ diff --git a/performance/plots/archive/block_driver_single_chache/metrics.jpg b/performance/plots/archive/block_driver_single_chache/metrics.jpg deleted file mode 100644 index 3d46934..0000000 Binary files a/performance/plots/archive/block_driver_single_chache/metrics.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/client_to_server.jpg b/performance/plots/archive/urpc_empty_loop/client_to_server.jpg deleted file mode 100644 index c5ecc16..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/client_to_server.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/metrics.jpg b/performance/plots/archive/urpc_empty_loop/metrics.jpg deleted file mode 100644 index 773bd18..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/metrics.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/performance.jpg b/performance/plots/archive/urpc_empty_loop/performance.jpg deleted file mode 100644 index 8154f42..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/performance.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/server_completed_task.jpg b/performance/plots/archive/urpc_empty_loop/server_completed_task.jpg deleted file mode 100644 index 2665361..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/server_completed_task.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/server_schedule_task.jpg b/performance/plots/archive/urpc_empty_loop/server_schedule_task.jpg deleted file mode 100644 index 8c018aa..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/server_schedule_task.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_empty_loop/server_to_client.jpg b/performance/plots/archive/urpc_empty_loop/server_to_client.jpg deleted file mode 100644 index e018775..0000000 Binary files a/performance/plots/archive/urpc_empty_loop/server_to_client.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/client_to_server.jpg b/performance/plots/archive/urpc_yield_loop/client_to_server.jpg deleted file mode 100644 index 0190817..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/client_to_server.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/metrics.jpg b/performance/plots/archive/urpc_yield_loop/metrics.jpg deleted file mode 100644 index 3293314..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/metrics.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/performance.jpg b/performance/plots/archive/urpc_yield_loop/performance.jpg deleted file mode 100644 index 103f8d0..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/performance.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/server_completed_task.jpg b/performance/plots/archive/urpc_yield_loop/server_completed_task.jpg deleted file mode 100644 index 0caf044..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/server_completed_task.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/server_schedule_task.jpg b/performance/plots/archive/urpc_yield_loop/server_schedule_task.jpg deleted file mode 100644 index 49dc3f7..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/server_schedule_task.jpg and /dev/null differ diff --git a/performance/plots/archive/urpc_yield_loop/server_to_client.jpg b/performance/plots/archive/urpc_yield_loop/server_to_client.jpg deleted file mode 100644 index ac3297d..0000000 Binary files a/performance/plots/archive/urpc_yield_loop/server_to_client.jpg and /dev/null differ diff --git a/performance/plots/block_driver/no_optimization.jpg b/performance/plots/block_driver/no_optimization.jpg new file mode 100644 index 0000000..ca98c57 Binary files /dev/null and b/performance/plots/block_driver/no_optimization.jpg differ diff --git a/performance/plots/block_driver/no_optimization.log b/performance/plots/block_driver/no_optimization.log new file mode 100644 index 0000000..a8379f3 --- /dev/null +++ b/performance/plots/block_driver/no_optimization.log @@ -0,0 +1,1383 @@ +picocom v3.1 + +port is : /dev/ttyUSB0 +flowcontrol : none +baudrate is : 115200 +parity is : none +databits are : 8 +stopbits are : 1 +escape is : C-a +local echo is : no +noinit is : no +noreset is : no +hangup is : no +nolock is : no +send_cmd is : sz -vv +receive_cmd is : rz -vv -E +imap is : +omap is : +emap is : crcrlf,delbs, +logfile is : none +initstring : none +exit_after is : not set +exit is : no + +Type [C-a] [C-h] to see available commands +Terminal ready +Starting download of 503 bytes + +downloading of 503 bytes finished +Starting download of 5618024 bytes +.......................................... +downloading of 5618024 bytes finished +## Executing script at 83200000 +Loading DeviceTree: imx8qxp-colibri-aster.dtb +120412 bytes read in 20 ms (5.7 MiB/s) +51 bytes read in 16 ms (2.9 KiB/s) +Applying Overlay: colibri-imx8x-aster_led6_overlay.dtbo +984 bytes read in 23 ms (41 KiB/s) +78Scanning disk usdhc@5b010000.blk... +Scanning disk usdhc@5b020000.blk... +Found 4 disks +Blob is at: 0xFC0F8BD0 +Magic: 12345678FEDCBA90 +Relocating ELF FC0F0000 FC63EBD0 1 +Relocating ELF FC0B2000 FC63FBD0 161 +Relocated CPU driver entry point is FFFF0000FC0B37E0, stack at FC0AE000 +Relocating multiboot info: FBBA5000 +FBBA5008: tag 1:32 +FBBA5028: tag 19:56 + before 1000:1CD7 + after FBBA8000:FBBA8CD7 +FBBA5060: tag 19:48 + before 2000:4914F + after FBBA9000:FBBF014F +FBBA5090: tag 19:48 + before 4A000:103DDF + after FBBF1000:FBCAADDF +FBBA50C0: tag 19:56 + before 104000:1891A7 + after FBCAB000:FBD301A7 +FBBA50F8: tag 19:48 + before 18A000:202DA7 + after FBD31000:FBDA9DA7 +FBBA5128: tag 19:48 + before 203000:2786FF + after FBDAA000:FBE1F6FF +FBBA5158: tag 19:56 + before 279000:2EE597 + after FBE20000:FBE95597 +FBBA5190: tag 19:48 + before 2EF000:36AB97 + after FBE96000:FBF11B97 +FBBA51C0: tag 19:48 + before 36B000:3E0557 + after FBF12000:FBF87557 +FBBA51F0: tag 19:48 + before 3E1000:48A43F + after FBF88000:FC03143F +FBBA5220: tag 19:64 + before 48B000:5065B7 + after FC032000:FC0AD5B7 +Allocating 512 L1 tables (2097152B) +L1 tables start at 0xFB9A4000 +Terminating boot services and jumping to image at 0xFC0F0000 +Core data pointer is FB9A3000 +Memory map at FC644860, key: 47, descriptor version: 1 +Got 29 memory map entries of 40B (1160B). +Type PStart PEnd Size Attributes + available 0000000080200000 0000000083FFFFFF 63488kB 8 + reserved 0000000084000000 00000000861FFFFF 34816kB 8 + available 0000000086200000 0000000087FFFFFF 30720kB 8 + reserved 0000000088000000 000000009001FFFF 131200kB 8 + available 0000000090020000 00000000901FFFFF 1920kB 8 + reserved 0000000090200000 00000000904FFFFF 3072kB 8 + available 0000000090500000 0000000091FFFFFF 27648kB 8 + reserved 0000000092000000 0000000094BFFFFF 45056kB 8 + available 0000000094C00000 00000000FB9A2FFF 1685132kB 8 + BF core data 00000000FB9A3000 00000000FB9A3FFF 4kB 8 +BF page table 00000000FB9A4000 00000000FBBA4FFF 2052kB 8 + BF multiboot 00000000FBBA5000 00000000FBBA7FFF 12kB 8 + BF module 00000000FBBA8000 00000000FC0ADFFF 5144kB 8 + BF stack 00000000FC0AE000 00000000FC0B1FFF 16kB 8 + BF code 00000000FC0B2000 00000000FC0F0FFF 252kB 8 + LD code 00000000FC0F1000 00000000FC648FFF 5472kB 8 + reserved 00000000FC649000 00000000FC64CFFF 16kB 8 + BS data 00000000FC64D000 00000000FC64DFFF 4kB 8 + RS data 00000000FC64E000 00000000FC64EFFF 4kB 8 + BS data 00000000FC64F000 00000000FC650FFF 8kB 8 + reserved 00000000FC651000 00000000FC655FFF 20kB 8 + BS data 00000000FC656000 00000000FC657FFF 8kB 8 + RS data 00000000FC658000 00000000FC658FFF 4kB 8 + reserved 00000000FC659000 00000000FC65CFFF 16kB 8 + RS data 00000000FC65D000 00000000FC65DFFF 4kB 8 + reserved 00000000FC65E000 00000000FC65EFFF 4kB 8 + LD data 00000000FC65F000 00000000FFE6FFFF 57412kB 8 + RS code 00000000FFE70000 00000000FFE7FFFF 64kB 8 + LD data 00000000FFE80000 00000000FFFFFFFF 1536kB 8 +Barrelfish CPU driver starting on ARMv8 (BSP) +kernel 0: ARMv8-A: Global data at 0xffff000080200000 +kernel 0: ARMv8-A: Kernel stack at 0xffff0000fc0ae000.. 0xffff0000fc0b1ff0 +kernel 0: ARMv8-A: Kernel first byte at 0xffff0000fc0b2000 +kernel 0: ARMv8-A: Exception vectors (VBAR_EL1): 0xffff0000fc0b2800 +kernel 0: ARMv8-A: 4 cores in system +kernel 0: ARMv8-A: Initializing the interrupt controller +kernel 0: GICv3: Initializing +kernel 0: GICD IIDR implementer=0x43b, revision=0x1, variant=0x1,prodid=0x0 +kernel 0: gic: #INTIDs supported: 544 +kernel 0: GICv3: Initialized +kernel 0: GICv3: Enabling CPU interface +kernel 0: GICv3: CPU interface enabled +kernel 0: ARMv8-A: Enabling timers +kernel 0: isr_el1=0x0 +System counter frequency is 8000000Hz. +Timeslice interrupt every 640000 ticks (80ms). +kernel 0: ARMv8-A: Setting coreboot spawn handler +kernel 0: ARMv8-A: Calling arm_kernel_startup +kernel 0: ARMv8-A: Doing BSP related bootup +start_free_ram = 0x80201000 +kernel 0: ARMv8-A: spawning 'armv8/sbin/init' on BSP core +kernel 0: ARMv8-A: spawn_init_common armv8/sbin/init +spawn module: armv8/sbin/init +kernel 0: init page tables: l0=0xffff000080520000, l1=0xffff000080521000, l2=0xffff000080522000, l3=0xffff000080523000 +load_init_image 0xffff0000fbbf1000 000b9ddf +kernel 0: ARMv8-A: init loaded with entry=0x4003a4 and GOT=0x46bc70 +kernel 0: ARMv8-A: Calling dispatch from arm_kernel_startup, entry point 0x4003a4 +init.0.0: initializing dynamic heap +init.0.0: running main on staticthread! +init.0.0: init domain starting on core 0 (IMX8X), invoked as: init 2097152 +init.0.0: grading_setup_bsp_init(argc=2) +init.0.0: mm_add: adding region. base=805f8000, size=3a08000 +init.0.0: mm_add: adding region. base=86200000, size=1e00000 +init.0.0: mm_add: adding region. base=90020000, size=1e0000 +init.0.0: mm_add: adding region. base=90500000, size=1b00000 +init.0.0: mm_add: adding region. base=94c00000, size=66da3000 +init.0.0: Added 1762 MB of physical memory. +init.0.0: Segment 0 load address 0x0, file size 1376, memory size 0x560 LOAD +init.0.0: Segment 1 load address 0x4a0, file size 192, memory size 0xc0 SKIP +init.0.0: Segment 2 load address 0x0, file size 0, memory size 0x0 SKIP +kernel 0: ARMv8-A: Timer interrupt received! +init.0.0: Segment 0 load address 0x0, file size 251224, memory size 0x3d558 LOAD +init.0.0: Segment 1 load address 0x3d498, file size 192, memory size 0xc0 SKIP +init.0.0: Segment 2 load address 0x0, file size 0, memory size 0x0 SKIP +init.0.0: Relocating image. +init.0.0: Relocating image. +init.0.0: [coreboot] Flush the cache +kernel 0: Invoking PSCI on: cpu=0x1, entry=0x80840004, context=0x80889000 +Barrelfish CPU driver starting on ARMv8 (APP) mpid=0:0:0:1 +init.0.0: paging_init_onthread thread id: 1 +kernel 1: ARMv8-A: Global data at 0xffff000080200000 +init.0.0: paging_init_onthread thread id: 2 +kernel 1: ARMv8-A: Kernel stack at 0xffff00008088a000.. 0xffff00008089a000 +init.0.0: Allocated pid 1 for process "block_driver_server". +kernel 1: ARMv8-A: Kernel first byte at 0xffff000080841000 +init.0.0: [spawn_load_elf_from_multiboot] block_driver_server +kernel 1: ARMv8-A: Exception vectors (VBAR_EL1): 0xffff000080841800 +init.0.0: SPAWN: multiboot mapped block_driver_server, size: 505271, magic: 7f ELF +kernel 1: GICv3: Enabling CPU interface +init.0.0: [spawn_load_argv] creating cspace +kernel 1: GICv3: CPU interface enabled +kernel 1: ARMv8-A: Enabling timers +kernel 1: isr_el1=0x0 +init.0.0: Allocated pid 2 for process "enet". +System counter frequency is 8000000Hz. +init.0.0: [spawn_load_elf_from_multiboot] enet +Timeslice interrupt every 640000 ticks (80ms). +init.0.0: SPAWN: multiboot mapped enet, size: 545191, magic: 7f ELF +kernel 1: ARMv8-A: Setting coreboot spawn handler +init.0.0: [spawn_load_argv] creating cspace +kernel 1: ARMv8-A: Calling arm_kernel_startup +kernel 1: ARMv8-A: Doing non-BSP related bootup +init.0.0: paging_init_onthread thread id: 3 +kernel 1: ARMv8-A: Memory: 8089a000, 80e04000, size=5544 kB +block_driver_ser.0.0: initializing dynamic heap +kernel 1: ARMv8-A: spawning 'armv8/sbin/init' on APP core +init.0.3: SPAWN: Received child init_chan endpoint +kernel 1: ARMv8-A: spawn_init_common armv8/sbin/init +block_driver_ser.0.0: Received child init OK +spawn module: armv8/sbin/init +enet.0.0: initializing dynamic heap +kernel 1: init page tables: l0=0xffff000080ba0000, l1=0xffff000080ba1000, l2=0xffff000080ba2000, l3=0xffff000080ba3000 +init.0.3: SPAWN: Received child init_chan endpoint +kernel 1: ARMv8-A: creating monitor URPC frame cap +enet.0.0: Received child init OK +kernel 1: ARMv8-A: mapping URPC frame cap 8081d000 +block_driver_ser.0.0: paging_init_onthread thread id: 1 +kernel 1: ARMv8-A: loading elf 'armv8/sbin/init' @ ffff0000fbbf1000 +enet.0.0: paging_init_onthread thread id: 1 +kernel 1: ARMv8-A: init loaded with entry=0x4003a4 and GOT=0x46bc70 +enet.0.1: Enet driver started +kernel 1: ARMv8-A: init dcb set up +[block_driver_server] initializing sdhc driver +kernel 1: ARMv8-A: Calling dispatch from arm_kernel_startup, entry point 0x4003a4 +armv8/sbin/init.1.0: initializing dynamic heap +armv8/sbin/init.1.0: running main on staticthread! +armv8/sbin/init.1.0: init domain starting on core 1 (IMX8X), invoked as: armv8/sbin/init 0 chanid=0 archid=0 +armv8/sbin/init.1.0: [app_main] +armv8/sbin/init.1.0: paging_init_onthread thread id: 1 +armv8/sbin/init.1.0: [app_main]: received bootinfo with 42 regions +armv8/sbin/init.1.0: grading_setup_app_init(bi=0x80007feaa0) +armv8/sbin/init.1.0: paging_init_onthread thread id: 2 +kernel 1: ARMv8-A: Timer interrupt received! +enet.0.1: [enet] Starting autonegotiation +[block_driver_server] registering +[block_driver_server] listening +[block_driver_server] incoming connection +block_driver_ser.0.1: [ump_chan_init] Each channel is 4096 bytes +[block_driver_server] connection ready to receive requests +init.0.0: [ump_chan_init] Each channel is 4096 bytes +init.0.0: [fat32_init] +block_driver_ser.0.1: [block_driver_server] read block 0 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 104887015 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 111287196 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 111287213 +[block_driver_server] incoming connection +block_driver_ser.0.1: [ump_chan_init] Each channel is 4096 bytes +[block_driver_server] connection ready to receive requests +armv8/sbin/init.1.0: [ump_chan_init] Each channel is 4096 bytes +armv8/sbin/init.1.0: [fat32_init] +block_driver_ser.0.1: [block_driver_server] read block 0 +init.0.0: [is_fat32] check fat type +init.0.0: Message handler loop +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 115127399 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 118967382 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 118967398 +armv8/sbin/init.1.0: [is_fat32] check fat type +init.0.0: Allocated pid 3 for process "echoserver". +armv8/sbin/init.1.0: [spawn_load_elf_from_multiboot] echoserver +armv8/sbin/init.1.0: SPAWN: multiboot mapped echoserver, size: 506775, magic: 7f ELF +armv8/sbin/init.1.0: [spawn_load_argv] creating cspace +echoserver.1.0: initializing dynamic heap +init.0.0: Allocated pid 4 for process "filereader". +armv8/sbin/init.1.0: [spawn_load_elf_from_multiboot] filereader +armv8/sbin/init.1.0: SPAWN: multiboot mapped filereader, size: 693311, magic: 7f ELF +armv8/sbin/init.1.0: [spawn_load_argv] creating cspace +filereader.1.0: initializing dynamic heap +init.0.0: Allocated pid 5 for process "shelly". +armv8/sbin/init.1.0: [spawn_load_elf_from_multiboot] shelly +armv8/sbin/init.1.0: SPAWN: multiboot mapped shelly, size: 480599, magic: 7f ELF +armv8/sbin/init.1.0: [spawn_load_argv] creating cspace +armv8/sbin/init.1.0: Message handler loop +armv8/sbin/init.1.0: SPAWN: Received child init_chan endpoint +echoserver.1.0: Received child init OK +armv8/sbin/init.1.0: SPAWN: Received child init_chan endpoint +filereader.1.0: Received child init OK +shelly.1.0: initializing dynamic heap +armv8/sbin/init.1.0: SPAWN: Received child init_chan endpoint +shelly.1.0: Received child init OK +echoserver.1.0: paging_init_onthread thread id: 1 +filereader.1.0: paging_init_onthread thread id: 1 +shelly.1.0: paging_init_onthread thread id: 1 +shelly.1.1: welcome to shelly! +shelly.1.1: libc exit NYI! +Echo server: registering +Filereader test +initializing filesystem... +Echo server: listening +[block_driver_server] incoming connection +block_driver_ser.0.1: [ump_chan_init] Each channel is 4096 bytes +[block_driver_server] connection ready to receive requests +filereader.1.1: [ump_chan_init] Each channel is 4096 bytes +filereader.1.1: [fat32_init] +block_driver_ser.0.1: [block_driver_server] read block 0 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 243163009 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 246971684 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 246971700 +filereader.1.1: [is_fat32] check fat type +SUCCESS: fs init took 0 ms + +------------------------------- +test_read_dir(/sdcard/) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 253387377 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 257211987 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 257211999 +TRASH-~1 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 258496923 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 262332171 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 262332185 +HELLO +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 262975088 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 266812351 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 266812364 +filereader.1.1: [fat32_closedir] +SUCCESS: test_read_dir took 2345 ms +------------------------------- + +------------------------------- +test_read_dir(/not-exist) +SUCCESS: failure expected test_read_dir took 479 ms +------------------------------- + +------------------------------- +test_fwrite(/sdcard/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 282834347 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 286652934 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 286652946 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 286838380 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 290493074 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 290493089 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 290678477 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 294333226 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 294333239 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 294518625 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 298173380 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 298173391 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 298358858 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 302013539 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 302013551 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 302198958 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 305853663 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 305853670 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 309693778 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 309944017 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 313533918 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 313533926 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 317374048 +file opened +wrote 70 bytes +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 321223063 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 325054307 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 325054315 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 325239733 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 328894457 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 328894462 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 332734569 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 332984638 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 336574698 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 336574703 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 340414824 +SUCCESS: test_fwrite took 7869 ms +------------------------------- + +------------------------------- +test_fread(/sdcard/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 348115824 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 351935276 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 351935288 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 352121001 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 355775431 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 355775439 +File size is 70 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 0 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 357122288 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 360895510 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 360895516 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 361080875 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 364735655 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 364735661 +read: I love deadlines. I like the whooshing sound they make as they fly by. +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 0 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 366125248 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 369855815 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 369855820 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 370041208 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 373695936 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 373695942 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 70 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 373939991 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 377536086 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 377536092 +SUCCESS: test_fread took 4340 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 385235633 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 389056513 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 389056527 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 389241924 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 392896644 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 392896655 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 393082000 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 396736791 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 396736805 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 396922225 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 400576931 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 400576942 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 400762326 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 404417076 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 404417078 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 408257224 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 408507266 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 412097350 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 412097360 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 415937484 +block_driver_ser.0.1: [block_driver_server] read block 123049 +block_driver_ser.0.1: [block_driver_server] write block 123049 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 416187477 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 419777622 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 419777631 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 423617745 +block_driver_ser.0.1: [block_driver_server] read block 123050 +block_driver_ser.0.1: [block_driver_server] write block 123050 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 423867714 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 427457901 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 427457908 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 431298030 +block_driver_ser.0.1: [block_driver_server] read block 123051 +block_driver_ser.0.1: [block_driver_server] write block 123051 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 431548031 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 435138194 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 435138204 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 438978285 +block_driver_ser.0.1: [block_driver_server] read block 123052 +block_driver_ser.0.1: [block_driver_server] write block 123052 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 439228266 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 442818427 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 442818437 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 446658560 +block_driver_ser.0.1: [block_driver_server] read block 123053 +block_driver_ser.0.1: [block_driver_server] write block 123053 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 446908578 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 450498690 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 450498698 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 454338833 +block_driver_ser.0.1: [block_driver_server] read block 123054 +block_driver_ser.0.1: [block_driver_server] write block 123054 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 454588879 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 458178984 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 458178993 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 462019090 +block_driver_ser.0.1: [block_driver_server] read block 123055 +block_driver_ser.0.1: [block_driver_server] write block 123055 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 462269096 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 465859260 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 465859271 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 469699392 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 469949461 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 473539541 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 473539544 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 477379688 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 477629706 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 481219844 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 481219847 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 485059976 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 485309969 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 488900107 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 488900113 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 492740235 +SUCCESS: test_make_dir took 14109 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 500444571 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 504260599 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 504260613 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 504446061 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 508100766 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 508100776 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 508286175 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 511940891 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 511940904 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 512126268 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 515781034 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 515781045 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 515966470 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 519621132 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 519621144 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 519806614 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 523461214 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 523461215 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 527301323 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: [block_driver_server] write block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 527551394 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 531141452 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 531141458 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 534981599 +block_driver_ser.0.1: [block_driver_server] read block 123057 +block_driver_ser.0.1: [block_driver_server] write block 123057 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 535231611 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 538821730 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 538821739 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 542661860 +block_driver_ser.0.1: [block_driver_server] read block 123058 +block_driver_ser.0.1: [block_driver_server] write block 123058 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 542911908 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 546502002 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 546502009 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 550342135 +block_driver_ser.0.1: [block_driver_server] read block 123059 +block_driver_ser.0.1: [block_driver_server] write block 123059 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 550592130 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 554182276 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 554182283 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 558022416 +block_driver_ser.0.1: [block_driver_server] read block 123060 +block_driver_ser.0.1: [block_driver_server] write block 123060 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 558272464 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 561862564 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 561862573 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 565702695 +block_driver_ser.0.1: [block_driver_server] read block 123061 +block_driver_ser.0.1: [block_driver_server] write block 123061 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 565952756 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 569542807 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 569542812 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 573382948 +block_driver_ser.0.1: [block_driver_server] read block 123062 +block_driver_ser.0.1: [block_driver_server] write block 123062 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 573632995 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 577223086 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 577223094 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 581063218 +block_driver_ser.0.1: [block_driver_server] read block 123063 +block_driver_ser.0.1: [block_driver_server] write block 123063 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 581313219 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 584903352 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 584903359 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 588743479 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: [block_driver_server] write block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 588993573 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 592583607 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 592583610 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 596423717 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: [block_driver_server] write block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 596673688 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 600263876 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 600263878 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 604104010 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 604354022 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 607944164 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 607944168 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 611784299 +SUCCESS: test_make_dir took 14429 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 619483800 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 623304649 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 623304662 +SUCCESS: failure expected test_make_dir took 1140 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent-directory) +SUCCESS: failure expected test_make_dir took 640 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent.txtt) +SUCCESS: failure expected test_make_dir took 480 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 650203293 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 654025442 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 654025456 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 654210827 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 657865585 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 657865598 +SUCCESS: failure expected test_rm_dir took 1620 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/parent/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 665568547 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 669385962 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 669385977 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 669571404 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 673226114 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 673226124 +block_driver_ser.0.1: [block_driver_server] read block 123056 +ERROR: echoserver.1 in main() /workspaces/aos2022-rueegges-hand-in/usr/echoserver/main.c:145 +ERROR: Failed to connect to net server +Failure: ( libaos) The requested server is not yet registered [LIB_ERR_UMP_NOT_REGISTERED] +Aborted +echoserver.1.1: libc exit NYI! +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 673411510 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 677066247 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 677066262 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 677251682 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 680906378 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 680906381 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 681091822 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 684746507 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 684746509 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 688586633 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 688836544 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 692426770 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 692426774 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 692612101 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 696266908 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 696266911 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 696452280 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 700107060 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 700107063 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 703947182 +SUCCESS: test_rm_dir took 5468 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 710365175 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 714187373 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 714187385 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 714372809 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 718027510 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 718027520 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 718212866 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 721867641 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 721867646 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 722053124 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 725707803 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 725707806 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 729547901 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 729797828 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 733388069 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 733388073 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 733573379 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 737228192 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 737228194 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 737413575 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 741068340 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 741068343 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 744908475 +SUCCESS: test_rm_dir took 4828 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/not-exist) +SUCCESS: failure expected test_rm_dir took 479 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 757730258 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 761549057 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 761549068 +SUCCESS: failure expected test_rm_dir took 980 ms +------------------------------- + +------------------------------- +test_rm_file(/sdcard/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 767971306 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 771789287 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 771789300 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 771974663 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 775629439 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 775629442 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 775814915 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 779469581 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 779469582 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 783309705 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 783559622 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 787149841 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 787149844 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 787335173 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 790989966 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 790989971 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 791175350 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 794830088 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 794830090 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 798670185 +SUCCESS: test_rm_file took 4348 ms +------------------------------- + +------------------------------- +test_rm_file(/sdcard/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 804452472 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 808270512 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 808270524 +SUCCESS: failure expected test_rm_file took 980 ms +------------------------------- + +------------------------------- +test_make_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 814690053 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 818510821 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 818510835 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 818696185 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 822350970 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 822350981 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 822536327 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 826191109 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 826191119 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 826376517 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 830031217 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 830031226 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 830216586 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 833871376 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 833871380 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 837711504 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 837961507 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 841551620 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 841551631 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 845391768 +block_driver_ser.0.1: [block_driver_server] read block 123041 +block_driver_ser.0.1: [block_driver_server] write block 123041 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 845641726 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 849231902 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 849231911 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 853072017 +block_driver_ser.0.1: [block_driver_server] read block 123042 +block_driver_ser.0.1: [block_driver_server] write block 123042 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 853322028 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 856912151 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 856912157 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 860752288 +block_driver_ser.0.1: [block_driver_server] read block 123043 +block_driver_ser.0.1: [block_driver_server] write block 123043 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 861002267 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 864592427 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 864592436 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 868432555 +block_driver_ser.0.1: [block_driver_server] read block 123044 +block_driver_ser.0.1: [block_driver_server] write block 123044 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 868682568 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 872272701 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 872272711 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 876112846 +block_driver_ser.0.1: [block_driver_server] read block 123045 +block_driver_ser.0.1: [block_driver_server] write block 123045 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 876362811 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 879952990 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 879952997 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 883793130 +block_driver_ser.0.1: [block_driver_server] read block 123046 +block_driver_ser.0.1: [block_driver_server] write block 123046 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 884043116 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 887633274 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 887633281 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 891473418 +block_driver_ser.0.1: [block_driver_server] read block 123047 +block_driver_ser.0.1: [block_driver_server] write block 123047 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 891723418 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 895313537 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 895313542 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 899153662 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 899403701 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 902993799 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 902993803 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 906833946 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 907083870 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 910674094 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 910674096 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 914514229 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 914764180 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 918354364 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 918354366 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 922194457 +SUCCESS: test_make_dir took 13949 ms +------------------------------- + +------------------------------- +test_fwrite_big(/sdcard/parent/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 927983768 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 931794794 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 931794806 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 931980247 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 935634915 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 935634928 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 935820310 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 939475062 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 939475075 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 939660464 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 943315204 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 943315214 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 943500592 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 947155346 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 947155358 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 947340741 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 950995484 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 950995494 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 951180875 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 954835586 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 954835596 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 955021003 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 958675724 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 958675726 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 962515831 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 962765873 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 966355977 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 966355981 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 970196110 +file opened +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 971530910 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 975316269 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 975316275 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: [block_driver_server] write block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 975501681 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 979156409 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 979156419 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 982996537 +block_driver_ser.0.1: [block_driver_server] read block 123049 +block_driver_ser.0.1: [block_driver_server] write block 123049 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 983246513 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 986836667 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 986836674 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 990676740 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 990926792 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 994516885 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 994516890 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 998357007 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 998654771 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1002197153 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1002197157 +block_driver_ser.0.1: [block_driver_server] read block 123050 +block_driver_ser.0.1: [block_driver_server] write block 123050 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1002383934 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1006037298 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1006037307 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1009877428 +block_driver_ser.0.1: [block_driver_server] read block 123051 +block_driver_ser.0.1: [block_driver_server] write block 123051 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1010130239 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1013717574 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1013717579 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1017557690 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1017810478 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1021397820 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1021397822 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1025237944 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1025538470 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1029078063 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1029078067 +block_driver_ser.0.1: [block_driver_server] read block 123052 +block_driver_ser.0.1: [block_driver_server] write block 123052 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1029265557 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1032918210 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1032918220 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1036758346 +block_driver_ser.0.1: [block_driver_server] read block 123053 +block_driver_ser.0.1: [block_driver_server] write block 123053 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1037011080 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1040598458 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1040598464 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1044438595 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1044691341 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1048278725 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1048278726 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1052118871 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1052419413 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1055959004 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1055959008 +block_driver_ser.0.1: [block_driver_server] read block 123054 +block_driver_ser.0.1: [block_driver_server] write block 123054 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1056146499 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1059799147 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1059799152 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1063639286 +block_driver_ser.0.1: [block_driver_server] read block 123055 +block_driver_ser.0.1: [block_driver_server] write block 123055 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1063892017 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1067479410 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1067479420 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1071319529 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1071572319 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1075159674 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1075159675 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1078999808 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1079300328 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1082839952 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1082839958 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1083027379 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1086680107 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1086680112 +block_driver_ser.0.1: [block_driver_server] read block 32 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1086867534 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1090520240 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1090520253 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1090707765 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1094360377 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1094360389 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1094547890 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1098200522 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1098200524 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1102040628 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: [block_driver_server] write block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1102293430 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1105880799 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1105880806 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1109720929 +block_driver_ser.0.1: [block_driver_server] read block 123057 +block_driver_ser.0.1: [block_driver_server] write block 123057 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1109973712 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1113561062 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1113561067 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1117401187 +block_driver_ser.0.1: [block_driver_server] read block 123058 +block_driver_ser.0.1: [block_driver_server] write block 123058 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1117653947 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1121241320 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1121241326 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1125081460 +block_driver_ser.0.1: [block_driver_server] read block 123059 +block_driver_ser.0.1: [block_driver_server] write block 123059 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1125334252 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1128921604 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1128921610 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1132761743 +block_driver_ser.0.1: [block_driver_server] read block 123060 +block_driver_ser.0.1: [block_driver_server] write block 123060 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1133014490 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1136601881 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1136601889 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1140442020 +block_driver_ser.0.1: [block_driver_server] read block 123061 +block_driver_ser.0.1: [block_driver_server] write block 123061 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1140694803 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1144282165 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1144282173 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1148122281 +block_driver_ser.0.1: [block_driver_server] read block 123062 +block_driver_ser.0.1: [block_driver_server] write block 123062 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1148375046 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1151962418 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1151962424 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1155802547 +block_driver_ser.0.1: [block_driver_server] read block 123063 +block_driver_ser.0.1: [block_driver_server] write block 123063 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1156055271 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1159642686 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1159642694 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1163482829 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1163735530 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1167322951 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1167322956 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1167510396 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1171163078 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1171163080 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1175003213 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: [block_driver_server] write block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1175255981 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1178843352 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1178843357 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1182683500 +block_driver_ser.0.1: [block_driver_server] read block 123057 +block_driver_ser.0.1: [block_driver_server] write block 123057 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1182936295 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1186523626 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1186523633 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1190363741 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1190616509 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1194203904 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1194203905 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1198044046 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1198344575 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1201884197 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1201884201 +block_driver_ser.0.1: [block_driver_server] read block 123058 +block_driver_ser.0.1: [block_driver_server] write block 123058 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1202071682 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1205724342 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1205724350 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1209564493 +block_driver_ser.0.1: [block_driver_server] read block 123059 +block_driver_ser.0.1: [block_driver_server] write block 123059 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1209817292 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1213404630 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1213404639 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1217244752 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1217497510 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1221084874 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1221084876 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1224925013 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1225203865 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1228765140 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1228765143 +block_driver_ser.0.1: [block_driver_server] read block 123060 +block_driver_ser.0.1: [block_driver_server] write block 123060 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1228952595 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1232605258 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1232605268 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1236445404 +block_driver_ser.0.1: [block_driver_server] read block 123061 +block_driver_ser.0.1: [block_driver_server] write block 123061 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1236698187 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1240285528 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1240285530 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1244125679 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1244378437 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1247965799 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1247965805 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1251805942 +SUCCESS: test_fwrite_big took 40990 ms +------------------------------- + +------------------------------- +test_fread_big(/sdcard/parent/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1258234538 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1262046211 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1262046222 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1262233674 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1265886334 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1265886348 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1266074118 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1269726452 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1269726456 +File size is 6702 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 0 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1273625538 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1277406702 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1277406707 +block_driver_ser.0.1: [block_driver_server] read block 123048 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1277594158 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1281246853 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1281246866 +block_driver_ser.0.1: [block_driver_server] read block 123049 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1281434326 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1285086989 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1285086998 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 1024 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1285334174 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1288927124 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1288927130 +block_driver_ser.0.1: [block_driver_server] read block 123050 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1289114552 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1292767257 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1292767268 +block_driver_ser.0.1: [block_driver_server] read block 123051 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1292954710 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1296607399 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1296607410 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 2048 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1296854617 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1300447527 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1300447530 +block_driver_ser.0.1: [block_driver_server] read block 123052 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1300634918 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1304287681 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1304287691 +block_driver_ser.0.1: [block_driver_server] read block 123053 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1304475101 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1308127826 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1308127837 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 3072 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1308375010 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1311967961 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1311967965 +block_driver_ser.0.1: [block_driver_server] read block 123054 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1312155388 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1315808090 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1315808099 +block_driver_ser.0.1: [block_driver_server] read block 123055 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1315995550 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1319648235 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1319648245 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 4096 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1319895468 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1323488376 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1323488381 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1323675810 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1327328522 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1327328527 +block_driver_ser.0.1: [block_driver_server] read block 123056 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1327515936 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1331168662 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1331168674 +block_driver_ser.0.1: [block_driver_server] read block 123057 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1331356092 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1335008790 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1335008800 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 5120 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1335256025 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1338848926 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1338848930 +block_driver_ser.0.1: [block_driver_server] read block 123058 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1339036308 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1342689068 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1342689078 +block_driver_ser.0.1: [block_driver_server] read block 123059 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1342876496 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1346529211 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1346529223 +filereader.1.1: [fat32_fread] on 0x9ffba0: 1024 bytes from offset 6144 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1346776389 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1350369328 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1350369334 +block_driver_ser.0.1: [block_driver_server] read block 123060 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1350556755 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1354209482 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1354209493 +block_driver_ser.0.1: [block_driver_server] read block 123061 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1354396939 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1358049633 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1358049638 +SUCCESS: test_fread_big took 12981 ms +------------------------------- + +------------------------------- +test_delete_open_file(/sdcard/parent/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1363843061 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1367649961 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1367649973 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1367837452 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1371490097 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1371490107 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1371677903 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1375330222 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1375330231 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1375517685 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1379170337 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1379170349 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1379357837 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1383010493 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1383010497 +SUCCESS: failure expected test_delete_open_file took 2901 ms +------------------------------- + +------------------------------- +test_delete_open_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1389434882 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1393250833 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1393250843 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1393438638 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1397090960 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1397090970 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1397278479 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1400931104 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1400931116 +filereader.1.1: [fat32_closedir] +SUCCESS: failure expected test_delete_open_dir took 1945 ms +------------------------------- + +------------------------------- +test_rm_file(/sdcard/parent/myfile2.txt) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1407358283 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1411171415 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1411171427 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1411358909 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1415011545 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1415011555 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1415198984 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1418851670 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1418851673 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: [block_driver_server] write block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1419039201 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1422691793 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1422691798 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1426531912 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1426784621 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1430372009 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1430372012 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1430559410 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1434212128 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1434212132 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1434399565 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1438052287 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1438052287 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1441892430 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1442145156 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1445732577 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1445732581 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1445920006 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1449572731 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1449572736 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1449760192 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1453412871 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1453412873 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1457252981 +SUCCESS: test_rm_file took 6749 ms +------------------------------- + +------------------------------- +test_rm_dir(/sdcard/parent) +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1463031127 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1466853285 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1466853300 +block_driver_ser.0.1: [block_driver_server] read block 123040 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1467040779 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1470693420 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1470693432 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1470880911 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1474533567 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1474533572 +block_driver_ser.0.1: [block_driver_server] read block 121920 +block_driver_ser.0.1: [block_driver_server] write block 121920 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1474721095 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1478373695 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1478373697 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1482213840 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1482466563 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1486053987 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1486053990 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:start 1486241412 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:memcpy 1489894122 +block_driver_ser.0.1: MEASUREMENT block_driver_read_object:done 1489894126 +block_driver_ser.0.1: [block_driver_server] read block 33 +block_driver_ser.0.1: [block_driver_server] write block 33 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:start 1490081615 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:read 1493734254 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:memcpy 1493734259 +block_driver_ser.0.1: MEASUREMENT block_driver_write_object:done 1497574380 +SUCCESS: test_rm_dir took 4829 ms +------------------------------- +filereader.1.1: libc exit NYI! + +Terminating... +Thanks for using picocom diff --git a/performance/plots/block_driver/no_sleep.log b/performance/plots/block_driver/no_sleep.log new file mode 100644 index 0000000..d0e02f6 Binary files /dev/null and b/performance/plots/block_driver/no_sleep.log differ diff --git a/performance/plots/block_driver/optimizations.jpg b/performance/plots/block_driver/optimizations.jpg new file mode 100644 index 0000000..e6ff5df Binary files /dev/null and b/performance/plots/block_driver/optimizations.jpg differ