Re: [Bug-xorriso] Xorriso slow in ISO creation

[Thomas Schmitt]

Hi,

i now suspect that much of the longer time is due to fsync(2) calls
in libburn's burn drive emulation.

See below, where "libburn/write.c" is mentioned, if you want to skip
the chronology of me getting to that conclusion.


> 10:37:35.145339 write(2, "xorriso : UPDATE :  0.18% done\n", 31) = 31
> 10:37:35.145610 nanosleep({0, 100000000}, NULL) = 0
> ...
> 10:37:36.050642 gettimeofday({1396863456, 50716}, {4294967236, 0}) = 0
> 10:37:36.050901 write(2, "xorriso : UPDATE :  79.10% done\n", 32) = 32
> [...]
> There seems to be lots of nanosleep call.

This is the pacifier loop of the boss thread during image stream
production. There are three threads active at that time:
xorriso boss, libisofs image producer, libburn image consumer thread.
At that stage, the company is up and running, so the boss can be lazy.

The boss is the one who spends time building the libisofs tree model.
Since we see here a whole second of image production, the tree model
building cannot be the culprit for 1.3 seconds total runtime.
(Unless you experienced a much longer runtime with the strace run.)

The next suspect is probably the emulation of a burn drive by libburn.
It has an adjustable fsync(2) interval in order to be nearer to DVD+RW
behavior and not to clog the system buffers.

Does xorriso get more competitive if you disable this syncing ?

   time xorriso -stdio_sync off -as mkisofs -R -J -o xorriso.iso xen


For me it makes a difference of 5.9 versus 4.7 seconds on a 160 MB
directory tree after much practicing of the system cache.
No difference can be seen as soon as the disk has to rattle for reading.

Comparing xorriso -stdio_sync off with genisoimage here, shows that both
reach the 100% output after less than 2 seconds. xorriso reports three times
that it is at 100% (probably finally syncing) whereas genisoimage just
ends. 

So i now look why there are these final seconds when xorriso waits
and the disk is busy.
The only occurence of fsync() is in

libburn/write.c , function burn_stdio_sync_cache() :

        d->needs_sync_cache = 0;
        if (!(flag & 1))
                libdax_msgs_submit(libdax_messenger, -1, 0x00000002,
                           LIBDAX_MSGS_SEV_DEBUG, LIBDAX_MSGS_PRIO_ZERO,
                           "syncing cache (stdio fsync)", 0, 0);
        ret = fsync(fd);
        if (ret != 0 && errno == EIO) {
                BURN_ALLOC_MEM(msg, char, 160);

                sprintf(msg,
                  "Cannot write desired amount of data. fsync(2) returned %d.",
                  ret);

It gets called intermediately if -stdio_sync is "on".
It gets called finally even if -stdio_sync is "off".

If i remove the fsync(fd) statement, then xorriso is done in 2.1 seconds
where genisoimage needs 1.7 seconds.

So please try what happens if you remove the only fsync() call from
libburn/write.c.
(If you installed xorriso from a binary package, then please get
   http://www.gnu.org/software/xorriso/xorriso-1.3.6.pl01.tar.gz
 unpack, cd xorriso-1.3.6, remove fsync(fd), do ./configure && make.
 Then test with the resulting binary ./xorriso/xorriso.
 No need to install it unless it is better than the unpatched one.)

If this yields an improvement for your use case, then i will make
the final fsync() depend on the setting of xorriso's -stdio_sync.
(Currently the -stdio_sync info is not available in the function
 that decides to make the final fsync(). I will have to change
 the internal wiring of libburn.)


Have a nice day :)

Thomas