Description of problem:

Image-builder is able to create qcow2 or vmdk in 5 minutes. While the option image-installer requires around 20 minutes to complete the build.

To understand why the time steps on the image-installer is more while not on qcow2 and vmdk, we check I used the in the Journal logs for osbuild-composer and osbuild-worker process, However here we don't see where the time is spent.

Osbuild worker logs for "image-installer" type. Build time tool from "05:11" to "05:37"
~~~
Jun 28 05:11:49 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:11:49-04:00" level=info msg="Running job 'b31928d3-0ca6-4ad3-adf8-1ae098308898' (osbuild)\n"
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="build pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.selinux success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="os pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.fix-bls success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.locale success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.timezone success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.sysconfig success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.selinux success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="anaconda-tree pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.rpm success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.buildstamp success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.locale success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.users success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.anaconda success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.lorax-script success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.dracut success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.selinux.config success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="bootiso-tree pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.bootiso.mono success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.kickstart success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.discinfo success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.tar success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg="bootiso pipeline results:\n" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.xorrisofs success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:10-04:00" level=info msg=" org.osbuild.implantisomd5 success" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:15 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:15-04:00" level=info msg="osbuild job succeeded" jobId=b31928d3-0ca6-4ad3-adf8-1ae098308898
Jun 28 05:37:16 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:37:16-04:00" level=info msg="Job 'b31928d3-0ca6-4ad3-adf8-1ae098308898' (osbuild) finished"
~~~

Osbuild worker logs for "qcow2" type. Build time tool from "05:41" to "05:48"
~~~
Jun 28 05:41:00 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:41:00-04:00" level=info msg="Running job '1f630898-462a-4346-9472-3fdbcc8e353d' (osbuild)\n"
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg="build pipeline results:\n" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.rpm success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.selinux success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg="os pipeline results:\n" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.rpm success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.fix-bls success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.locale success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.timezone success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.systemd success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.sysconfig success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.rhsm success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.fstab success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.grub2 success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.selinux success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg="image pipeline results:\n" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.truncate success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.sfdisk success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.lvm2.create success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.mkfs.fat success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.mkfs.xfs success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.copy success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.lvm2.metadata success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.grub2.inst success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg="qcow2 pipeline results:\n" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:10 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:10-04:00" level=info msg=" org.osbuild.qemu success" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:11 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:11-04:00" level=info msg="osbuild job succeeded" jobId=1f630898-462a-4346-9472-3fdbcc8e353d
Jun 28 05:48:11 rhel8.test.example.com osbuild-worker[1747]: time="2022-06-28T05:48:11-04:00" level=info msg="Job '1f630898-462a-4346-9472-3fdbcc8e353d' (osbuild) finished"
~~~

We see that the vmdk image has only 3 pipelines , i.e. build pipeline , image pipeline and qcow2 pipeline.
While the iso creation has many more. However we cant see from here exactly where the time can be spent.

I see that this only list the information about various pipelines , and it gets updated at the same time at the end of the build process and are not in real time.
From the above logs we see that timing which is showing in the `time=` field are pretty much continuous across various build pipelines , and does not really show where the time is spent.

When I do the `composer-cli compose log <UUID>` the logs which show up does not have any timing and most of the information is about the packages and other than that there is very little information on what its doing.

Also the output which is generated by `# composer-cli compose logs <UUID>` for both the build only one file is generated on extraction the tar file i.e. `logs/osbuild.log`
It has most of the information about the packages but does not have timestamps or information about other stages.

Version-Release number of selected component (if applicable):

cockpit-composer-36-1.el8.noarch
osbuild-53-2.el8.noarch
osbuild-composer-46.3-1.el8_6.x86_64
osbuild-composer-core-46.3-1.el8_6.x86_64
osbuild-composer-dnf-json-46.3-1.el8_6.x86_64
osbuild-composer-worker-46.3-1.el8_6.x86_64
osbuild-luks2-53-2.el8.noarch
osbuild-lvm2-53-2.el8.noarch
osbuild-ostree-53-2.el8.noarch
osbuild-selinux-53-2.el8.noarch
python3-osbuild-53-2.el8.noarch
weldr-client-35.5-1.el8.x86_64

How reproducible:
Every time

Steps to Reproduce:
1. Create image for image-installer type and monitor the logs. We need to wait 20 mins for it to complete and the logs are updated at the end of the build process.

1. composer-cli compose start test-blueprint image-installer
2. journalctl -b -f -t osbuild-worker

2. Create image for the qcow2 or vmdk type and monitor the logs. It get completed in around 5 mins and logs are updated to journal at the end of the build process.

1. composer-cli compose start test-blueprint qcow2
2. journalctl -b -f -t osbuild-worker

3. Check the logs file generated for both the build process and we see that it does not have time stamps and or what stage took more time, time to help understand why it may have been slow.

1. composer-cli compose logs <UUID of image-installer type>
2. composer-cli compose logs <UUID of qcow2 type>

Actual results:
Image creation for "image-installer" type take more time i.e. 20 mins to complete compared to vmdk/qcow2 which takes around 5 mins to complete.

Expected results:
To understand how the image creation time for "image-installer" type be improved upon.

Additional info:
I have raised a separate RFE for adding real-time logs and enabling more verbosity to image creation process - https://bugzilla.redhat.com/show_bug.cgi?id=2101763 while raising this for the slow creation of "image-installer" compose type.