write_bootable_mmc: add per-phase timing output

write_bootable_mmc.py

@@ -52,6 +52,20 @@ def shout(cmd):
     """Execute shell command and print to console"""
     subprocess.call(cmd, shell=True)
 
+def timestamp():
+    """Return human-readable local timestamp."""
+    return time.strftime("%Y-%m-%d %H:%M:%S")
+
+def begin_phase(name):
+    """Start a timed phase."""
+    print(f"[{timestamp()}] {name}")
+    return time.monotonic()
+
+def end_phase(name, start_t):
+    """Finish a timed phase."""
+    elapsed = time.monotonic() - start_t
+    print(f"[{timestamp()}] {name} done in {elapsed:.1f}s")
+
 def print_help():
     """Print help information"""
     print("\nDescription:\n")
@@ -307,20 +321,26 @@ if something_is_missing:
     sys.exit(1)
 
 # Main execution
-print(f"= Erase partition table on {DEVICE} and everything else")
+overall_start = time.monotonic()
+print(f"[{timestamp()}] Starting SD preparation for {DEVICE}")
+
+t_phase = begin_phase(f"= Erase partition table on {DEVICE} and everything else")
 shout(f"dd if=/dev/zero of={DEVICE} bs=512 count=2")
 shout(f"dd if=/dev/zero of={DEVICE} bs=1MB count=1 seek=1")
 shout(f"dd if=/dev/zero of={DEVICE} bs=1MB count=1 seek={BOOT_SIZE}")
+end_phase("Erase", t_phase)
 
-print("= Create partition table")
+t_phase = begin_phase("= Create partition table")
 shout(f"parted -s {DEVICE} mktable {PT_TYPE}")
+end_phase("Partition table", t_phase)
 
-print("= Create partitions")
+t_phase = begin_phase("= Create partitions")
 shout(f"parted -s {DEVICE} mkpart primary {BOOT_FS} 1 {BOOT_SIZE}")
 shout(f"parted -s {DEVICE} mkpart primary {ROOT_FS} {BOOT_SIZE + 1} 100%")
 # Check alignment
 shout(f"parted -s {DEVICE} align-check optimal 1")
 shout(f"parted -s {DEVICE} align-check optimal 2")
+end_phase("Partition creation", t_phase)
 
 # Wait for device nodes to be created
 devs_created = False
@@ -330,7 +350,7 @@ if os.path.basename(DEVICE)[-1].isdigit():
     partition1 = f"{DEVICE}p1"
     partition2 = f"{DEVICE}p2"
 
-print("= Waiting for device nodes...")
+t_phase = begin_phase("= Waiting for device nodes...")
 while not devs_created:
     if os.path.exists(partition1) and os.path.exists(partition2):
         devs_created = True
@@ -338,39 +358,44 @@ while not devs_created:
         print(".", end="", flush=True)
         time.sleep(0.5)
 print()
+end_phase("Device node wait", t_phase)
 
 time.sleep(1)
-print("= Format partitions")
+t_phase = begin_phase("= Format partitions")
 
 shout(f"mkfs.vfat {partition1} -F 32 -n {BOOT_LABEL}")
 shout(f"mkfs.ext4 {partition2} -F -L {ROOT_LABEL}")
+end_phase("Formatting", t_phase)
 
 # Create temporary mount point
 shout("mkdir -p tmp")
 
 if IMAGE_FILE == "":
     # Copy boot files
-    print("= Copying boot files...")
+    t_phase = begin_phase("= Copying boot files...")
     shout(f"mount {partition1} tmp")
     for i in BOOT_FILE_LIST:
         print(f"    {i}")
         shout(f"cp {i} tmp")
     shout("umount tmp")
+    end_phase("Boot files copy", t_phase)
 
     # Extract root filesystem
-    print("= Extracting root filesystem...")
+    t_phase = begin_phase("= Extracting root filesystem...")
     shout(f"mount {partition2} tmp")
     shout(f"tar -C tmp/ -xzpf {ROOT_ARCHIVE}")
     shout("umount tmp")
+    end_phase("Rootfs extract", t_phase)
 else:
     # Copy from image file
-    print("= Copying from image file...")
+    t_phase = begin_phase("= Copying from image file...")
     shout("modprobe dm-mod")
     shout(f"kpartx -av {IMAGE_FILE}")
+    end_phase("Image attach", t_phase)
     
     # Wait for mapper devices
     devs_created = False
-    print("= Waiting for mapper devices...")
+    t_phase = begin_phase("= Waiting for mapper devices...")
     while not devs_created:
         if os.path.exists("/dev/mapper/loop0p1") and os.path.exists("/dev/mapper/loop0p2"):
             devs_created = True
@@ -378,30 +403,36 @@ else:
             print(".", end="", flush=True)
             time.sleep(0.5)
     print()
+    end_phase("Mapper device wait", t_phase)
     
     shout("mkdir -p tmp2")
     
     # Copy boot partition
-    print("= Copying boot partition...")
+    t_phase = begin_phase("= Copying boot partition...")
     shout(f"mount {partition1} tmp")
     shout("mount /dev/mapper/loop0p1 tmp2")
     shout("rsync -a tmp2/ tmp")
     shout("umount tmp")
     shout("umount tmp2")
+    end_phase("Boot partition copy", t_phase)
     
     # Copy root partition
-    print("= Copying root partition...")
+    t_phase = begin_phase("= Copying root partition...")
     shout(f"mount {partition2} tmp")
     shout("mount /dev/mapper/loop0p2 tmp2")
     shout("rsync -a tmp2/ tmp")    
     shout("umount tmp")
     shout("umount tmp2")
+    end_phase("Root partition copy", t_phase)
     
     shout("rm -rf tmp2")
+    t_phase = begin_phase("= Detaching image mappers...")
     shout(f"kpartx -dv {IMAGE_FILE}")
+    end_phase("Image detach", t_phase)
 
 # Clean up
 shout("rm -rf tmp")
 
-print("\nDone! SD card is ready for use.")
+total_elapsed = time.monotonic() - overall_start
+print(f"\n[{timestamp()}] Done! SD card is ready for use in {total_elapsed:.1f}s.")
 print(f"You can now safely remove {DEVICE}")