open / libsystem_kernel.dylib slow on first run for any .img

Developer Tools & Services General
nathan-pierce-veertu OP
Created 1d
Replies 5
Boosts 0
Views 65
Participants 1

We see a major delay for the first open("disk.img", O_RDONLY); we perform.

If it helps, we use clonefile() to copy a sparsed image.

if (-1 == (fd = open(path, (mode & O_ACCMODE) | O_CLOEXEC)))
        return -1;

1791 Thread_1071327   DispatchQueue_1: com.apple.main-thread  (serial)
      1791 start  (in dyld) + 6076  [0x189f72b98]
        1791 main  (in anka_image) + 20  [0x102171bb8]
          1791 clp_main  (in libpolicy.dylib) + 2120  [0x102a49eac]
            1790 process_info  (in anka_image) + 68  [0x1021723f4]
            + 1790 vdsk_open  (in libvdsk.dylib) + 92  [0x1021d90e8]
            +   1790 vdsk_open_native  (in libvdsk.dylib) + 164  [0x1021d91c0]
            +     1790 open  (in libsystem_kernel.dylib) + 64  [0x18a2dd6a4]
            +       1790 __open  (in libsystem_kernel.dylib) + 8  [0x18a2d2678]

What advice do you have for diagnosing what is causing the first open to do this? Is this some sort of security scan happening? Indexing?

Replies  5
Boosts  0
Views  65
Participants  1
nathan-pierce-veertu OP
1d

I created a simple app that simulates creating a new APFS IMAGE and then tests the performance of open calls and I see, while not major delays, similar delay on the first call consistently

iteration 01 open()    0.017 ms (fd=3)
iteration 02 open()    0.010 ms (fd=3)
iteration 03 open()    0.009 ms (fd=3)
iteration 04 open()    0.009 ms (fd=3)
iteration 05 open()    0.009 ms (fd=3)
iteration 06 open()    0.009 ms (fd=3)
iteration 07 open()    0.008 ms (fd=3)
iteration 08 open()    0.009 ms (fd=3)
iteration 09 open()    0.008 ms (fd=3)
iteration 10 open()    0.009 ms (fd=3)
iteration 11 open()    0.008 ms (fd=3)
iteration 12 open()    0.008 ms (fd=3)
0
nathan-pierce-veertu OP
1d

Running a test comparing the overhead between regular open and what we do in anka:

❯ ./run.sh
Creating sparse APFS image with hdiutil (2048 MiB cap, volume BenchAPFS) → /Users/nathanpierce/apfs-open-repro/disk.dmg
created: /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage
Note: hdiutil wrote /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage (-type SPARSE uses .sparseimage beside the requested name).
 Done. Image stats:
-rw-r--r--  1 nathanpierce  staff    10M May 14 13:55 /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage

clonefile(2): /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage → /Users/nathanpierce/apfs-open-repro/disk_clone.dmg
Clone stats:
-rw-r--r--  1 nathanpierce  staff    10M May 14 13:55 /Users/nathanpierce/apfs-open-repro/disk_clone.dmg

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Original sparse image
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

=== Phase 1: bare open(2) / close (baseline) ===
Bench: ./bench_open /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage 12
opening /Users/nathanpierce/apfs-open-repro/disk.dmg.sparseimage for 12 consecutive open/close rounds

iteration 01 open()    0.011 ms (fd=3)
iteration 02 open()    0.009 ms (fd=3)
iteration 03 open()    0.009 ms (fd=3)
iteration 04 open()    0.008 ms (fd=3)
iteration 05 open()    0.008 ms (fd=3)
iteration 06 open()    0.008 ms (fd=3)
iteration 07 open()    0.008 ms (fd=3)
iteration 08 open()    0.008 ms (fd=3)
iteration 09 open()    0.008 ms (fd=3)
iteration 10 open()    0.008 ms (fd=3)
iteration 11 open()    0.008 ms (fd=3)
iteration 12 open()    0.008 ms (fd=3)
Phase 2: attached /dev/disk21 (read-only) — GPT/NXSB use decoded sectors (UDIF-safe).

=== Phase 2: Anka-style stack (vdsk_native fcntls + fstat [+DKIOC] + GPT + NXSB) ===
Bench: ./bench_anka_style_open /dev/disk21 12

iteration 01 anka-style    2.451 ms (open+fcntl    1.332 ms, ioctl yes, gpt+nxsb skip/err)
iteration 02 anka-style    0.554 ms (open+fcntl    0.047 ms, ioctl yes, gpt+nxsb skip/err)
iteration 03 anka-style    0.977 ms (open+fcntl    0.496 ms, ioctl yes, gpt+nxsb skip/err)
iteration 04 anka-style    1.040 ms (open+fcntl    0.364 ms, ioctl yes, gpt+nxsb skip/err)
iteration 05 anka-style    1.485 ms (open+fcntl    1.395 ms, ioctl yes, gpt+nxsb skip/err)
iteration 06 anka-style    1.577 ms (open+fcntl    0.645 ms, ioctl yes, gpt+nxsb skip/err)
iteration 07 anka-style    1.381 ms (open+fcntl    1.020 ms, ioctl yes, gpt+nxsb skip/err)
iteration 08 anka-style    2.357 ms (open+fcntl    1.508 ms, ioctl yes, gpt+nxsb skip/err)
iteration 09 anka-style    0.500 ms (open+fcntl    0.069 ms, ioctl yes, gpt+nxsb skip/err)
iteration 10 anka-style    1.413 ms (open+fcntl    0.722 ms, ioctl yes, gpt+nxsb skip/err)
iteration 11 anka-style    0.195 ms (open+fcntl    0.061 ms, ioctl yes, gpt+nxsb skip/err)
iteration 12 anka-style    0.653 ms (open+fcntl    0.099 ms, ioctl yes, gpt+nxsb skip/err)

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
clonefile(2) copy
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

=== Phase 1: bare open(2) / close (baseline) ===
Bench: ./bench_open /Users/nathanpierce/apfs-open-repro/disk_clone.dmg 12
opening /Users/nathanpierce/apfs-open-repro/disk_clone.dmg for 12 consecutive open/close rounds

iteration 01 open()    0.024 ms (fd=3)
iteration 02 open()    0.011 ms (fd=3)
iteration 03 open()    0.009 ms (fd=3)
iteration 04 open()    0.010 ms (fd=3)
iteration 05 open()    0.010 ms (fd=3)
iteration 06 open()    0.009 ms (fd=3)
iteration 07 open()    0.009 ms (fd=3)
iteration 08 open()    0.009 ms (fd=3)
iteration 09 open()    0.009 ms (fd=3)
iteration 10 open()    0.008 ms (fd=3)
iteration 11 open()    0.008 ms (fd=3)
iteration 12 open()    0.008 ms (fd=3)
Phase 2: attached /dev/disk21 (read-only) — GPT/NXSB use decoded sectors (UDIF-safe).

=== Phase 2: Anka-style stack (vdsk_native fcntls + fstat [+DKIOC] + GPT + NXSB) ===
Bench: ./bench_anka_style_open /dev/disk21 12

iteration 01 anka-style    3.146 ms (open+fcntl    1.300 ms, ioctl yes, gpt+nxsb skip/err)
iteration 02 anka-style    1.596 ms (open+fcntl    0.693 ms, ioctl yes, gpt+nxsb skip/err)
iteration 03 anka-style    1.148 ms (open+fcntl    0.607 ms, ioctl yes, gpt+nxsb skip/err)
iteration 04 anka-style    1.357 ms (open+fcntl    0.377 ms, ioctl yes, gpt+nxsb skip/err)
iteration 05 anka-style    0.994 ms (open+fcntl    0.680 ms, ioctl yes, gpt+nxsb skip/err)
iteration 06 anka-style    1.132 ms (open+fcntl    0.669 ms, ioctl yes, gpt+nxsb skip/err)
iteration 07 anka-style    0.087 ms (open+fcntl    0.032 ms, ioctl yes, gpt+nxsb skip/err)
iteration 08 anka-style    2.194 ms (open+fcntl    0.454 ms, ioctl yes, gpt+nxsb skip/err)
iteration 09 anka-style    1.149 ms (open+fcntl    0.334 ms, ioctl yes, gpt+nxsb skip/err)
iteration 10 anka-style    0.087 ms (open+fcntl    0.034 ms, ioctl yes, gpt+nxsb skip/err)
iteration 11 anka-style    1.940 ms (open+fcntl    0.884 ms, ioctl yes, gpt+nxsb skip/err)
iteration 12 anka-style    1.635 ms (open+fcntl    1.567 ms, ioctl yes, gpt+nxsb skip/err)

So we do see that each time we call open it's delayed for some reason, no matter if we're doing anything special.

Interesting that the clonefile() produced image does actually cause a bit more delay

0
nathan-pierce-veertu OP
1d

More context:

We initially thought it was the VM booting up from the image that was the cause as putting a sleep of 30 seconds between start and then when we do the open of the image eliminates the delay.

However, next time we start the VM (not re-cloning) there is no delay while it's booting.

This makes me suspect that there is some sort of security scan happening that's locking open up for us. But what exactly...

0
nathan-pierce-veertu OP
9h

https://feedbackassistant.apple.com/feedback/22784807

0
nathan-pierce-veertu OP
1h

Moderators, please delete this. I think we figured it out.

0
open / libsystem_kernel.dylib slow on first run for any .img
First post date Last post date
 
 
Q