Doing the same image with AutoDMG 1.7.1 takes really a long time

[ramuntcho]

Hi,

For years now, we are using in Geneva, Switzerland, AutoDMG to create our master, a big master with about 250 pkgs. I have made the same image (Sierra 12.2), with the same pkgs, using AutoDMG 1.6, 1.7 and 1.7.1.
If you look at logs (https://www.dropbox.com/sh/1obggcmvd3domfq/AAAQM288hU0xehDSTP4Vg-E9a?dl=0), your see that it takes :

• with AutoDMG 1.6, about 2h30
• with AutoDMG 1.7, about 2h (great !!!)
• with AutoDMG 1.7.1, about 7h

I have made the test 2 times with the last version and i don't understand why the last version acts like that.

Many thanks in advance (and many thanks to make AutoDMG available, it's a great tool for us).

Christian

[MagerValp]

The bulk of the time difference is in disk image conversion, which is limited by I/O performance. In your 1.6 and 1.7 runs you save to /Volumes/Sauvegarde poste instaDMG, whereas in 1.7.1 you're saving to /Volumes/Vierge. Is perhaps Vierge slower than Sauvegarde poste instaDMG?

[ramuntcho]

Thanks for the answer, but that's not the problem. I made normally all my images on Disk Vierge.

To test, i have made an other image on /Volumes/Sauvegarde poste instaDMG yesterday and it takes more than 6,5 hours with version 1.7.1. See log : https://www.dropbox.com/s/fcg4xz3fiyqcg4c/AutoDMG_2016-12-20_08.40_version%201.7.1.log?dl=0

Christian

[MagerValp]

Thank you, that eliminates one variables, and indeed that wasn't the problem. I've been looking at the logs some more, and something really weird is going on in 1.7.1. The time measurements for the phases are all wrong, it's like the clock isn't working correctly. Look at 1.7:

2016-12-16 16:41:12 Info: Phase Installing 410OpenBoard1.3.4SEM.pkg with weight 175063040 finished after 6.646 seconds
2016-12-16 16:41:13 Info: Phase Installing 410PrefsWacom.pkg with weight 104865792 finished after 1.423 seconds
2016-12-16 16:41:15 Info: Phase Installing 410UtilitaireOpenBoard.pkg with weight 105701376 finished after 1.557 seconds
2016-12-16 16:41:17 Info: Phase Installing 500PourFinir.pkg with weight 154365952 finished after 2.461 seconds
2016-12-16 16:42:15 Info: Phase Installing 500PourFinirLogAProteger.pkg with weight 1947279360 finished after 58.009 seconds
2016-12-16 16:53:23 Info: Phase Converting disk image with weight 328204288 finished after 667.807 seconds
2016-12-16 16:53:30 Info: Phase Scanning disk image with weight 2097152 finished after 7.303 seconds
2016-12-16 16:53:31 Info: Phase Scanning disk image with weight 1048576 finished after 1.327 seconds
2016-12-16 17:06:39 Info: Phase Scanning disk image with weight 157286400 finished after 787.983 seconds
2016-12-16 17:06:53 Info: Phase Scanning disk image with weight 17825792 finished after 12.726 seconds

Notice how the time that it says the phase takes matches the time elapsed in the log. Now look at 1.7.1:

2016-12-20 00:00:27 Info: Phase Installing 410OpenBoard1.3.4SEM.pkg with weight 175063040 finished after 0.023 seconds
2016-12-20 00:02:35 Info: Phase Installing 410PrefsWacom.pkg with weight 104865792 finished after 0.016 seconds
2016-12-20 00:04:56 Info: Phase Installing 410UtilitaireOpenBoard.pkg with weight 105701376 finished after 0.019 seconds
2016-12-20 00:06:50 Info: Phase Installing 500PourFinir.pkg with weight 243593216 finished after 0.016 seconds
2016-12-20 00:09:26 Info: Phase Installing 500PourFinirLogAProteger.pkg with weight 1947279360 finished after 0.048 seconds
2016-12-20 00:11:12 Info: Phase Converting disk image with weight 328204288 finished after 0.120 seconds
2016-12-20 00:11:32 Info: Phase Scanning disk image with weight 2097152 finished after 7760.123 seconds
2016-12-20 00:11:38 Info: Phase Scanning disk image with weight 1048576 finished after 0.010 seconds
2016-12-20 00:11:44 Info: Phase Scanning disk image with weight 157286400 finished after 0.008 seconds
2016-12-20 00:11:52 Info: Phase Scanning disk image with weight 17825792 finished after 0.010 seconds

It's completely off.

I can't think of any changes in 1.7.1 that would have this effect...

[MagerValp]

Attaching log files to issue:

log_1.6.txt
log_1.7.1.txt
log_1.7.txt

[ramuntcho]

I can't explain, i will try this evening with 1.7.3.

[ramuntcho]

Hi,
I have some presents for you, many logs :-))
I have made 3 tests with AutoDMG 1.6 and 1.7.3 :

• master with just the System 10.12.2 and Updates (iTunes)
• master mini with only 31 pkgs
• master complete

Here are the logs :
AutoDMG 2016-12-21 08.34_System_1.6.txt
AutoDMG 2016-12-21 14.23_System_1.7.3.txt
AutoDMG 2016-12-21 16.31_Mini_1.7.3.txt
AutoDMG 2016-12-21 23.48_Mini_1.6.txt
AutoDMG 2016-12-22 07.51_1.7.3.txt
AutoDMG 2016-12-22 11.40_1.6.txt

If we resume :

master System : 1h20 with version 1.6 / 53min with version 1.7.3
master mini : 2h25 with version 1.6 / 1h40 with version 1.7.3
master complete : 2h30 with version 1.6 / 6h40 with version 1.7.3

Quite strange, no ? Version AutoDMG 1.7.3 seems faster than 1.6 for small master (the mini is a dmg of about 12.4 Go), but not for the complete master (33.7 Go).

Christian

[MagerValp]

Wow, that's a lot of data, thank you! And these are all run on the same computer with the same config, the only difference is the version of AutoDMG used?

[ramuntcho]

Right :-((

[MagerValp]

Well, one mystery solved: the weird times in the log add up, but the time taken is wrong for each entry. There appears to be some kind of event coalescing happening, so at least we're not dealing with time travel :)

[jazzace]

OK, I think I have additional data on this problem. I, too, use AutoDMG to deploy a large number of packages — in my case, the sounds and loops that come with Logic Pro and/or GarageBand. In the current versions of those apps, you would deploy approx. 400-600 packages to get everything available for the product in question. (In earlier versions, there were fewer but larger packages.)

I was experiencing slowness on initial loading of the templates and how long it took to ask for admin authentication once I started the build — about two minutes for each, but that was not different from previous versions. The new problems I experienced were prolonged "beachballing", even after it appeared that the image was completed. Once previously, I had force quit AutoDMG when I could see a completed image in the Finder that seemed to have been asr-scanned and was subsequently able to use that image in a deployment workflow without issue.

Now to the new data. I ran a test yesterday where I created an 10.12.6 image with the 400+ packages the current version of GarageBand uses (and a handful of others) using AutoDMG 1.7.3 (508). I directed AutoDMG to save the completed image to an external USB 3.0 SSD (/Volumes/DSServer/). I left it to run overnight. It completed successfully, taking about 8.5 hours according to the log. The log file is here:

AutoDMG 2017-08-01 09.09.txt

Notice how time marches on fairly steadily in the logs. However, take a look at these two lines from when the image is being scanned for asr:

2017-08-01 00:01:55 Notice: Script phase: asr1
…
2017-08-01 00:02:07 Info: Phase Scanning disk image with weight 2097152 finished after 21600.693 seconds

Notice the discrepancy here. Scanning the disk image apparently took 6 hours even though the scan, according to the log, started 12 seconds earlier. So when I go to examine the completed image in the Finder (remembering that it was saved to an external volume), here's the date/time information:

Created: 15:56
Modified: 18:06

This suggests that it took AutoDMG 5 hours and 56 minutes to report that it had finished scanning the completed image. As a further test, I took that same completed image, duplicated it, and used Disk Utility to Scan Image for Restore. It took between 4 and 5 minutes. This seems to agree with the data above.

My conclusion from all this is that this is a problem with AutoDMG not being able to keep up its logging when numerous small packages (about 25% of which were less than 10 MB in size, in this case) are installed. So my install was done in about 2.5 hours, even though it did not finish reporting so until about 6 hours later.

[MagerValp]

Excellent sleuthing @jazzace, thank you! That narrows it down significantly and gives me a shot at reproducing it.

[jazzace]

I have one more piece of data that might help solve this problem, fully understanding that it might never get fixed.

Similar scenario to last year, just a more extreme example: installing ca. 700 packages as Additional software, almost all of which are sounds and loops for Logic Pro X, many of which are tiny.

Since AutoDMG was still beach balling when I returned in the morning, I decided to drop in to console to examine the log file there. It reported that, at 10:31:30 PM (yesterday), it was basically done: (IEDWorkflow:801) Finalize exited with status 0. So I decided to ride this out. Almost 12 hours after the log file in the user's Library/Logs/AutoDMG folder reported this, it finished. I then decided to save the log from the Log window in AutoDMG (i.e. clicking on the Save As… button) as I had done last year. Here's the log for this run:

AutoDMG 2018-07-25 Save As from Finder.log

I then decided to take a look at the log AutoDMG had left in ~/Library/Logs/AutoDMG. Here's a copy of that log:

AutoDMG-2018-07-24 ~Logs.log

I then examined them side-by-side in BBEdit. It didn't take me long to discover that, while the steps each file reported were the same (they both have exactly the same 40923 log lines, with one small sequence difference in lines 1460-1462), the times varied wildly. The version saved from the app's Log window showed a steady progression of real world time in the time stamps but did not align with how little time the log was reporting it took to install the packages (often 1 or 2 seconds). The log that was being saved to the user's log directory seemed to have time stamps more indicative of how little time it was taking to install some of the smaller packages, but some time stamps appeared to be "stuck" for a few seconds (or alternately, the install time report of 1 or 2 seconds was inaccurate and it took fractions of a second instead). We would then see a jump every so often.

I've rationalized the times and formats to make them easier to compare:

AutoDMG 2018-07-25 Save As from Finder match.log
AutoDMG-2018-07-24 ~Logs Match.log

And, because I have it, here's the ~/Library/Logs/AutoDMG log from last year's post:

AutoDMG-2017-07-31.log

My best guess — and it is only a guess — is that this might actually be a problem with the app's Log window (however you are writing to it) getting overwhelmed and not being able to process it in a timely fashion when being bombarded with small package installs. @ramuntcho reported that things changed for them in v.1.7.1, a version where you added features to the Log window. I'm wondering if it might be possible to revert those changes in a test build. I'll happily run it through its paces if you do.

[MagerValp]

@jazzace Awesome sleuthing! I'll take a stab at untangling the log code and see if I can isolate the troublesome section.