Bug 397732 - K3B: data project: when burning wrong size of written data is displayed
Summary: K3B: data project: when burning wrong size of written data is displayed
Status: RESOLVED FIXED
Alias: None
Product: k3b
Classification: Applications
Component: GUI/Usability (show other bugs)
Version: 18.04.1
Platform: Manjaro Linux
: NOR minor
Target Milestone: ---
Assignee: k3b developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-08-22 08:38 UTC by Armin Mohring
Modified: 2019-03-16 11:35 UTC (History)
5 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments
K3b 18.08.1 log, Arch Linux (122.30 KB, text/plain)
2018-09-25 16:37 UTC, Patrick Silva
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Armin Mohring 2018-08-22 08:38:18 UTC
Steps to Reproduce:
1. Start K3B
2. Create data project
3. USE DVD-R/RW
4. Start writing
5. Watch status bar (progress of x of y total data volume written)

Actual Results:  
Status bar stops *before* status bar stop at full data volume. 

Expected Results:  
Status bar stops at full data volume.

*It is a display error, since the DVD is completly written*
Comment 1 Leslie Zhai 2018-08-28 12:53:12 UTC
Hi Armin,

Thanks for your bug report!

Hi Thomas,

Please help Armin to generate some *log* files for my debugging, thanks a lot!

Regards,
Leslie Zhai
Comment 2 Thomas Schmitt 2018-08-28 14:05:19 UTC
Hi,

@Leslie:

I am the backend guy. Operating K3B is not really my turf and my K3B is old.
(But i just pulled the freshest code from git.)

@Armin Mohring:

As far as i can see, the numbers for the progress messages stem from
the writer modules k3bgrowisofswriter.cpp or k3bcdrecordwriter.cpp.
(Like "emit processedSize(...);".
They seem to take their numbers from message output of the respective
programs growisofs or cdrecord (or wodim).

When a burn run with my K3B has ended, then the window with the progress
bar offers a button "Show Debugging Output" (at the lower right).
There i can see the pacifier messages from growisofs.

In my try (with DVD+RW) the progress bar waited at 93 % until the medium
was ejected. Then it hopped to 100 %. But the text still says
  "755.0 MiB of 805.0 MiB"

This is halfways plausible from the view of K3B by the last pacifier
message of growisofs:

  807534592/859508736 (94.0%) @4.0x, remaining 0:09 RBU 100.0% UBU  99.7%

growisofs reports to have written 807534592 of 859508736 bytes
and to consider this as 94.0 percent of the job.

The "94 %" is very near to the "93 %" which i remember to have seen.
807534592/859508736 = .939530406355288. So it is plausible to see 93.
But 807534592 bytes = 770.125 MiB. 859508736 bytes = 819.69140625 MiB.
So why 755.0 and 805 ? (xorriso too says its 859508736 bytes.)

No further message is recorded from growisofs. That's strange.

A direct run of growisofs (with an ISO image of similar size) ends by 
    805109760/858783744 (93.8%) @4.0x, remaining 0:09 RBU 100.0% UBU  99.7%
    823623680/858783744 (95.9%) @4.0x, remaining 0:06 RBU 100.0% UBU  99.7%
    842104832/858783744 (98.1%) @4.0x, remaining 0:03 RBU  49.7% UBU  99.7%
  builtin_dd: 419328*2KB out @ average 3.9x1352KBps
  /dev/sr4: flushing cache
  /dev/sr4: stopping de-icing
  /dev/sr4: writing lead-out

In comparison, this looks as if K3B is not logging all messages from
growisofs, possibly because it does not receive them all.
The reasons for this would be out of my expertise.

Have a nice day :)

Thomas
Comment 3 Leslie Zhai 2018-08-29 01:27:37 UTC
(In reply to Thomas Schmitt from comment #2)
> Hi,
> 
> @Leslie:
> 
> I am the backend guy. Operating K3B is not really my turf and my K3B is old.
> (But i just pulled the freshest code from git.)

You are always my teacher :)

> 
> @Armin Mohring:
> 
> As far as i can see, the numbers for the progress messages stem from
> the writer modules k3bgrowisofswriter.cpp or k3bcdrecordwriter.cpp.

$ git log k3bgrowisofswriter.cpp or k3bcdrecordwriter.cpp

You lead me to fix BUG380064, BUG367639, BUG137436 and BUG372094.

> (Like "emit processedSize(...);".
> They seem to take their numbers from message output of the respective
> programs growisofs or cdrecord (or wodim).
> 
> When a burn run with my K3B has ended, then the window with the progress
> bar offers a button "Show Debugging Output" (at the lower right).
> There i can see the pacifier messages from growisofs.
> 
> In my try (with DVD+RW) the progress bar waited at 93 % until the medium
> was ejected. Then it hopped to 100 %. But the text still says
>   "755.0 MiB of 805.0 MiB"
> 
> This is halfways plausible from the view of K3B by the last pacifier
> message of growisofs:
> 
>   807534592/859508736 (94.0%) @4.0x, remaining 0:09 RBU 100.0% UBU  99.7%
> 
> growisofs reports to have written 807534592 of 859508736 bytes
> and to consider this as 94.0 percent of the job.
> 
> The "94 %" is very near to the "93 %" which i remember to have seen.
> 807534592/859508736 = .939530406355288. So it is plausible to see 93.
> But 807534592 bytes = 770.125 MiB. 859508736 bytes = 819.69140625 MiB.
> So why 755.0 and 805 ? (xorriso too says its 859508736 bytes.)
> 
> No further message is recorded from growisofs. That's strange.
> 
> A direct run of growisofs (with an ISO image of similar size) ends by 
>     805109760/858783744 (93.8%) @4.0x, remaining 0:09 RBU 100.0% UBU  99.7%
>     823623680/858783744 (95.9%) @4.0x, remaining 0:06 RBU 100.0% UBU  99.7%
>     842104832/858783744 (98.1%) @4.0x, remaining 0:03 RBU  49.7% UBU  99.7%

I need to find the root cause why K3B failed to receive the "full data volume", for example 98.1%. And I need to build growisofs for mips64el manually.
https://mail.kde.org/pipermail/k3b/2018-August/002201.html

Hi Armin, please directly run growisofs in your environment to double check, thanks!

>   builtin_dd: 419328*2KB out @ average 3.9x1352KBps
>   /dev/sr4: flushing cache
>   /dev/sr4: stopping de-icing
>   /dev/sr4: writing lead-out
> 
> In comparison, this looks as if K3B is not logging all messages from
> growisofs, possibly because it does not receive them all.
> The reasons for this would be out of my expertise.

It is my job :)

> 
> Have a nice day :)
> 
> Thomas
Comment 4 Patrick Silva 2018-09-25 16:37:29 UTC
Created attachment 115230 [details]
K3b 18.08.1 log, Arch Linux

I can confirm the behavior reported here with K3b 18.08.1 on Arch Linux.
I'm attaching my K3b log.
Comment 5 Armin Mohring 2019-03-16 09:50:36 UTC
I am using Manjaro with k3b version 18.12.3.
Now the written data size is reported correctly.
Solved!
Thanks!
Comment 6 Thomas Schmitt 2019-03-16 11:35:49 UTC
Hi,

Armin Mohring wrote:
> I am using Manjaro with k3b version 18.12.3.
> Now the written data size is reported correctly.
> Solved!

If some code change in K3B caused this improvement, then i fail to see it
in https://github.com/KDE/k3b/commits since summer 2018.
It might have been about a KDE change outside of K3B.


Back in august, i wanted to learn how k3bgrowisofswriter.cpp starts
growisofs and connects to its output channels. But i could not find
the implementation of this call:

        if( !d->process.start( KProcess::MergedChannels ) ) {

I expect that in the end the system call pipe(2) is employed.
Its man page gives a glimpse of an idea what might have happened:

  O_DIRECT (since Linux 3.4)
      Create a pipe that performs I/O in "packet" mode.
      [...]
      *  If a read(2) specifies a buffer size that is smaller than the
         next packet, then the requested number of bytes are read, and
         the  excess  bytes in the packet are discarded.

But as said, i got lost in the C++ jungle and could not confirm that
pipe(2) was used with flag O_DIRECT. Class GrowisofsWriter in
k3bgrowisofswriter.h has no member named "process". So "d->process" and
its member ".start()" are probably inherited from other classes.


Have a nice day :)

Thomas