Startup/Loading performance with external/spinning hard drives

[glouel]

Let's make a separate issue for performance stuff :

For me, I run it off a LaCie P9227 2TB USB C drive. I would agree that some delay could be accounted for by that, but as the rive is an SSD and USB-C I would think not this much delay. I can send you the log if you need me to as well, just let me know.

Originally posted by @ZV00 in #194 (comment)

[glouel]

First, let's start with the USB-C SSD one, as I do think we have 2 separate issues here (one common to both, one specific to you @ZV00) :

For me, I run it off a LaCie P9227 2TB USB C drive. I would agree that some delay could be accounted for by that, but as the rive is an SSD and USB-C I would think not this much delay. I can send you the log if you need me to as well, just let me know.

@ZV00
Please do, with milliseconds enabled, of a startup (please close syspref before taking the log) ! I spotted something weird in your previous log but since it lacked milliseconds I'd rather be sure, see here :

8:55:40 PM : avInit1 (2149.0, 461.0, 296.0, 184.0)
8:55:40 PM : <AerialView: 0x7ffc45402100> AerialView setup init
...
8:55:40 PM : Community JSON : 73 entries
8:55:43 PM : Total videos processed : 73

First two line is Aerial starting on that screen, everything ok. The second 2 lines show the moment when Aerial simply loads the json files and deduplicate those entries in memory. Those are the tvOS10.json, tvOS11.json and entries .json, there's only 4 files (one is in our bundle, 3 in cache folder) of a few kB. But Aerial also parse the header for each video to grab their duration (so add 73 requests).

Here's what I get on my 2015 iMac with a SSD for comparison :

2019-05-14 12:19:21.785 : Community JSON : 73 entries
2019-05-14 12:19:21.788 : Total videos processed : 73

And @gregarios with his Fusion Drive :

2019-05-14 18:25:12.217 : Community JSON : 73 entries
2019-05-14 18:25:12.217 : Total videos processed : 73

While USB-C is great in terms of throughput with one large file, the protocol used to do the file I/O between the OS and the drive is where it usually falls short for small accesses. If you happen to run in Bulk Only Transfer mode, all access are sequentials which could explain why it's so slow here for you (77 sequential requests). There's a better protocol called UASP that solves this, whether it's used or not depends on many things. I would suggest you have a look at this and give it a shot :

https://discussions.apple.com/thread/6164330?answerId=25764928022#25764928022

I would guess you will see IOUSBMassStorageClass (BOT) instead of IOUSBAttachedSCSI (UASP) for your drive, which could explain why that part is painfully slow for you. Please let me know ! I could probably workaround that, but let's see what you get on your end first.

[glouel]

Ok let's look at the second one here:

I'm running a 2017 iMac with Fusion Drive (so a fusion of a 128G SSD as a sort of cache with a 2TB HDD). All the videos are downloaded fully into cache, and I have the "streaming" diabled completely in your settings.

Ok that's good for settings !

Yes, it takes about 5 seconds to show the screensaver when activating it with either the main monitor alone or both together -- same amount of time.

Ok !

Attaching my AerialLog.txt:
AerialLog.txt

So first, you don't have the issue that @ZV00 seems to have, for the video processing, which is good.

But the log doesn't capture your slowdown:

2019-05-14 18:24:36.590 : avInit1 (0.0, 0.0, 2304.0, 1296.0)
2019-05-14 18:24:36.590 : <AerialView: 0x7fc6f7a00000> AerialView setup init

macOS starts Aerial on your iMac screen.

2019-05-14 18:24:36.605 : <AerialView: 0x7fc6f7a00000> observeValue Optional("readyForDisplay")

The video player (which is shared, and on main process) says it's ready, it starts playing just after that.

2019-05-14 18:24:36.606 : avInit1 (-1024.0, 16.0, 1024.0, 1280.0)
2019-05-14 18:24:36.606 : <AerialView: 0x7fc706d31c00> AerialView setup init

macOS starts Aerial on your second display.

2019-05-14 18:24:36.608 : <AerialView: 0x7fc6f7a00000> startAnimation
2019-05-14 18:24:36.608 : <AerialView: 0x7fc706d31c00> startAnimation

macOS gives us the synchronize go ahead on both screens to start everything

2019-05-14 18:24:36.721 : <AerialView: 0x7fc6f7a00000> observeValue Optional("readyForDisplay")

I get another readyForDisplay from the player, so at worse the playback starts here.

So we're talking 131ms here and for what it's worth, that's exactly how it looks on my iMac too. If you see a 5 second slowdown, it's probably happening after that point. I'll try to see if I can get an event when playback actually starts, to see if this is where it slows down or not. Will let you know.

Conjecture, it's possible that AVPlayer chokes on the play command for a few seconds, I don't remember if it preloads the whole video from disk. If it does, I can definitely see 5 seconds to load a 800 MB file from the spinnning part of your fusion drive. Let's see if I can track this better and what we can do.

[ZV00]

@glouel Attached below is my log:
AerialLog.txt

That first one was a slowdown of only a few second so I also did it a second time, the second time was much slower:

AerialLog.txt

[glouel]

@ZV00 did you close System preferences before taking the log ? I see 4 aerial view on the second one so I'm a bit puzzled !

Regarding the USB bit I talked about, it's instantaneous here too so your drive is probably in UASP mode right now which is good.

[ZV00]

I did, but here it is again (did the startup twice again the first is a bit faster than the second)
AerialLog.txt

EDIT:

Steps were as follows:

1. Open System Prefs>Screensavers, allow debug mode with all other boxes checked
2. Close system prefs
3. Enter screensaver using a key combo I have set
4. Let start
5. Wake from sleep, enter password
6. Wait a few moments
7. Repeat 3 onwards

[glouel]

Ok thanks a lot ! That's much easier to read for me, in that case I'm seeing the same thing I did in @gregarios, I'll try to get extra logging in and get back to you.

Edit : It kinda looks like it's the player choking as I suspected, especially since you mentioned first one was faster that second. Take a look at the videos played :

1st time : b6-4.mov, an old 1080p video of SF, 92.4 MB
2nd time : comp_L012_c002_PS_v01_SDR_PS_20180925_SDR_4K_HEVC.mov, a new 4K video of london, 293.1 MB

If I'm right, you can unselect all your videos (you can save them as a set with the bookmark icon if you have some favorites selected) and just select "Santa Monica Beach" in LA/day category. This is the biggest video, 823.7 MB so if you see a WAY worse hang, that's probably it.

[glouel]

@ZV00 (if you haven't see my edit above)

I posted beta4 with some extra logging when playback exactly starts.

You should now get in your logs something like this :

2019-05-15 15:33:35.667 : <AerialView: 0x7f84955037b0> observeValue Optional("readyForDisplay")
2019-05-15 15:33:35.668 : <AerialView: 0x7f84955037b0> observeValue Optional("rate")
2019-05-15 15:33:35.668 : video started playing

Could I ask you for another log with beta4, using your steps above. I would ask however to clear things up that you wait a specific time (roughly) before you press a key to get out of the screensaver, like 5 or 10 seconds from the moment you see the video fading in ? This would also be helpful to track where the slowdown appears. Many thanks !

[gregarios]

Attached is my log for beta4 too:
AerialLog.txt

I can tell you that the log doesn't appear to show when the initial delay is going on... the log says "video started playing" but there is a 5 second delay before it shows up on the screen. There is also a delay of 4 seconds between "keydown" and "stop and next" which appears to be the black time between videos showing in the skip-to-next feature.

[glouel]

Attached is my log for beta4 too:
AerialLog.txt

I can tell you that the log doesn't appear to show when the initial delay is going on... the log says "video started playing" but there is a 5 second delay before it shows up on the screen. There is also a delay of 4 seconds between "keydown" and "stop and next" which appears to be the black time between videos showing in the skip-to-next feature.

Thanks so much. The keyDown/stop and next is very telling indeed.

So just to be clear, when you press the right arrow key, does it start fading out to black immediately (if you have fades enabled) then stay black for 4-5 secs ? Am I understanding this correctly ?

I'm more puzzled than ever...

Here's what I have with 1sec fades FYI, the stop and next is logged just after the fade stop, and the keyDown before it starts:

2019-05-15 16:38:10.790 : keyDown
2019-05-15 16:38:12.069 : stop and next

[gregarios]

So just to be clear, when you press the right arrow key, does it start fading out to black immediately (if you have fades enabled) then stay black for 4-5 secs ? Am I understanding this correctly ?

I do have fade-in/out set to 2-seconds.
Ok so here is the sequence of events as they appear to me:

1. Key-press to go "next" — immediately it begins to fade toward black
2. Fading takes 3 full seconds to black. (note: not a completely even fade -- seems to fade toward black then "snap" to black near the very end)
3. One full second of black.
4. Fade to next video begins — lasting 2 full seconds until full apparent brightness. (more evenly fading than the fade-out)

[gregarios]

Hmmm... I set the fade in/out to "none" and it reveals something. Here is the sequence:

Initial load time to begin showing the first video (screensaver start): 4 seconds.
Key-press to go "next" — immediately "blinks" to black for about 1/8 of a second then shows the same image again (continuing the first video for another 1/8 second), then it switches to the next image with no black between them.

[glouel]

Hmmm... I set the fade in/out to "none"

I was just replying to you asking if you could try that :)

and it reveals something. Here is the sequence:

Initial load time to begin showing the first video (screensaver start): 4 seconds.
Ok that's still slow but let's put it aside a sec.

Key-press to go "next" — immediately "blinks" to black for about 1/8 of a second then shows the same image again (continuing the first video for another 1/8 second),

Yes I was typing that you'll see a tiny blink with no fade out as I messed up something. But that's ok it's just trying to fade for 0 seconds which give that flicker, I'll fix that one.

then it switches to the next image with no black between them.
So immediately-ish ?

That's a lot more normal. Maybe I have something else wrong with my fades considering the one you seem to see for 3 secs instead of two. Will need to think about that one, hmm !

Regarding the evenness, it's a cubic function fade so that can give that impression a bit, although it's supposed to be symetrical to the other one. Intriguing thanks for the confirmations.

[gregarios]

Regarding the evenness, it's a cubic function fade so that can give that impression a bit, although it's supposed to be symmetrical to the other one. Intriguing thanks for the confirmations.

It may in fact be symmetrical... but the eye isn't — we can judge with extreme detail the difference between black and very-little light, but we can't judge very well at all the difference between 100% bright and say, 90% brightness. I think maybe the fade-out should start normal but go slower as it reaches the end, while the fade-in could remain as is.

[glouel]

Yep agreed, maybe I should have said mirrored.

It's more the 3 sec duration that's weirding me out, it could be that there's some stalling happening, messing up the animation for it to run that long. Will do more checking thanks.

[ZV00]

AerialLog.txt

Attached log with Beta 4
Steps were:

1. Debug on
2. Launch
3. Hit right arrow
4. Exit, password
5. Pause
6. Launch screen saver
7. Exit, password

[glouel]

AerialLog.txt

Attached log with Beta 4
Steps were:

1. Debug on
2. Launch
3. Hit right arrow
4. Exit, password
5. Pause
6. Launch screen saver
7. Exit, password

Ok thanks. How did you setup your fades in video panel btw?

I'll try putting cache on a usb drive here to see if I can replicate here and catch whatever's happening.

[glouel]

Ok so, I managed to reproduce but this seems purely based on your disk speed (in bandwidth and I/O) and whether the file gets cached by the system or not.

Here's a way to show it pretty quickly, uncheck every video, and pick just "Santa Monica Beach" and LAX in LA videos, assuming you have those cached in 4K. I have Fades at 1s FYI.

• First launch, I had a good 4 sec lag that doesn't show in the logs.
• I press right arrow, fade comes instantly, but a good 4 sec of lag afterwarsds :

2019-05-16 11:43:06.304 : keyDown
2019-05-16 11:43:10.569 : stop
2019-05-16 11:43:10.570 : stop and next

Here, It's just loading the large santa monica video.

• Now both videos (or at least the beggining of the files) are cached in RAM by system somewhere. I press right arrow again :

2019-05-16 11:45:10.266 : keyDown
2019-05-16 11:45:11.471 : stop and next

I get instant switch and the time is about the fade time + loading time (about what I get here on iMac with SSD). If I keep pressing right arrow, I switch from one video to another with the same instantaneity.

@ZV00 & @gregarios can you give that a shot and confirm you get something similar?

[gregarios]

@ZV00 & @gregarios can you give that a shot and confirm you get something similar?

Yes it is a 4-sec delay for the first video, then they switch almost instantly after they are loaded once. Adding all the rest of the videos makes them all have 2-3 second load times during switching (with fade set to none) until it comes to the two we used in the test then those are instant. It does appear to be HD load times for such large files. Not sure you can really control that -- and caching the entire library isn't an option. Maybe pre-loading the "next" video in the background while the first is playing would help eliminate the delay -- so you'd never have more than 2 videos cached (to save RAM) but you'd still have all the benefit.

[glouel]

@gregarios awesome, thanks for confirming. The caching you see right now is system side.

There may be a way for me to start loading next video AVPlayer earlier which would help subsequent load but not the first one, for that one nothing I can do indeed.

edit : just adding some screenshots for documentation, please ignore: