Regression: slow playback performance after project settings have been set to match the assets (also: big CPU usage by the GTK Timeline)
Development in progress, NormalPublic

Description

Grab the usual métro 1.MOV (a great benchmark for fluidity, as always!) and insert it into a blank timeline. Play. Notice the playback is smooth.

Set the project settings from the clip properties, which means 1280x720 with a square PAR.

Result: playback is now extremely choppy, to the point of being unwatchable/unreliable for editing.

This also happens if you save the project and reload it afterwards.

This issue does not occur with 0.94.

Details

Commits
D484 / rPTVb33905607636: timeline: Do not show keyframes while playing
git URI
git@github.com:thiblahute/pitivi.git#wip/phab/T3348
jeff created this task.Oct 4 2015, 11:16 PM
jeff updated the task description. (Show Details)
jeff raised the priority of this task from to Blocker.
jeff assigned this task to thiblahute.
jeff added a project: Pitivi 0.95.
jeff moved this task to Backlog on the Pitivi 0.95 board.
jeff added a subscriber: jeff.
jeff added a comment.EditedOct 4 2015, 11:35 PM

Scrub-seeking by click-dragging is also slow as hell in this case (but not with the default 720x576 settings), there's no reason why it shouldn't be blazing fast.

Can you try to launch pitivi setting PITIVI_UNSTABLE_FEATURES=gtkglsink please?

jeff added a comment.Oct 18 2015, 3:49 PM

If I do that, I get a segfault when loading the project.
Couldn't launch with gdb to investigate that segfault, because:

$ gdb PITIVI_UNSTABLE_FEATURES=gtkglsink pitivi
Fatal Python error: Py_Initialize: Unable to get the locale encoding
ImportError: No module named 'encodings'
Abandon
thiblahute moved this task from Backlog to In progress on the Pitivi 0.95 board.Oct 18 2015, 5:21 PM
jeff added a comment.EditedOct 18 2015, 7:24 PM

Alright, noticing that individual seeks were extremely slow (1+ second), I realized there actually are two issues at play here:

  1. The GTK Timeline is dogslow. Hiding it brings back good performance for seeking and playback, as you can see in http://jeff.ecchi.ca/public/pitivi-T3348-gtktimeline-slow-seeks.mov ; this almost brings it on par with the medialibrary's previewer, which is lightning-fast
  2. Before hiding the timeline widget, there is still the weird phenomenon where the project settings' resolution impacts performance at higher (ex: HD) values, and it seems to have some weird amplification effect on the 1st issue. I really don't understand that one.

Regarding no2: with the timeline canvas turned off and setting the project settings to a resolution of 1280x720 (matching the clips), we can see that the CPU usage is 2-4 times higher than:

  • Project settings set to 320x180;
  • Playback at native resolution (1280x720) in the media library's previewer, which supposedly uses the same sink.
jeff renamed this task from Regression: slow playback performance after project settings have been set to match the assets to Regression: slow playback performance after project settings have been set to match the assets (also: big CPU usage by the GTK Timeline).Oct 18 2015, 7:57 PM
jeff added a comment.EditedOct 19 2015, 12:35 AM

Some additional samples for testing the playback smoothness difference between the media library's previewer and clips inserted into the timeline (with matching project settings):

When seeking in general, this profile seems to indicate that we redraw the timeline too much http://aleb.ro/pitivi/profile-scrubbing.svg

Seeing do_draw taking 11% and busMessageCb (which basically does nothing) taking 3% gives me the impression we are not doing anything bad... I mean drawing is actually doing quite a lot of things (and all synchronously) so it makes a lot of sense some time is spent in it.

I tried all your clips here, and it all works smoothly here :/

thiblahute moved this task from Backlog to Pitivi 0.95 on the Pitivi board.Oct 26 2015, 9:30 AM
thiblahute moved this task from Pitivi 0.95 to Backlog on the Pitivi board.Oct 26 2015, 9:35 AM
thiblahute added a comment.EditedOct 26 2015, 3:08 PM

OK, I have investigated that a little bit further doing some proper benchmarking and creating a benchmarking scripts:

that it would be nice you run doing just launching ./tests.py from the extracted folder.

I am getting the following results here:

Checking: pitivi --ges-sample-paths /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348 /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario

Processes average CPU usage:

python3 -- 169.823387
Xorg -- 8.680645
Checking: ges-launch-1.0 --ges-sample-paths file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348 --set-scenario /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario --videosink gtksink

Processes average CPU usage:

lt-ges-launch-1.0 -- 177.185714
Xorg -- 4.719643
Checking: gst-validate-1.0 playbin uri=file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/YE7VID_720_60_P_MVI_1921.MOV video-sink=gtksink

Processes average CPU usage:

lt-gst-validate-1.0 -- 51.132143
Xorg -- 6.058036
Checking: gst-launch-1.0 uridecodebin name=d uri=file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/YE7VID_720_60_P_MVI_1921.MOV ! queue ! videoconvert ! videoscale ! compositor ! videoconvert ! gtksink d. ! audioconvert ! audioresample ! audiomixer ! audioconvert ! audioresample ! autoaudiosink

Processes average CPU usage:

lt-gst-launch-1.0 -- 88.465179
Xorg -- 8.278571

conclusion

So we can clearly see that the problem is not directly linked to pitivi but rather to the pipeline GES creates and is this completely media related and UI related.

Now, I checked where time is spent in the pipeline running with gst-top and compare that to the simple pipeline (with compositor) I tested in my benchmarking and here are the results:

GES
GST_DEBUG=0 ./instruments/gst-top-1.0 ges-launch-1.0 --ges-sample-paths file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348 --set-scenario /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario --videosink gtksink

=========================================
Running scenario /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario on pipeline gespipeline0
=========================================
Executing  pause: 
Executing  add-layer: priority=0 
Executing  set-track-restriction-caps: track-type=video caps="video/x-raw\,\ framerate\=\(fraction\)25/1" 
Executing  add-asset: id=file:///home/thiblahute/Videos/pitivi/bugs/samples/YE7VID_720_60_P_MVI_1921.MOV type=GESUriClip 
Executing (subaction) add-clip: name=uriclip0 layer-priority=0 asset-id=file:///home/thiblahute/Videos/pitivi/bugs/samples/YE7VID_720_60_P_MVI_1921.MOV type=GESUriClip start=0:00:00.000000000 inpoint=0 duration=0:00:11.077733336 
Executing  commit: 
Executing  play: 
Executing  stop: playback-time=11 force=true 1.077733334 speed: 1.000000 />

/home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario --> State change request NULL, quiting application
   warning : a new segment event has different value than the received one
             Detected on <smart-adder-adder:src>
             Detected on <smart-mixer-mixer:src>
             Description : when receiving a new segment, an element should push an equivalentsegment downstream

   warning : a serialized event received should be pushed in the same 'time' as it was received
             Detected on <smart-adder-adder:src>
             Detected on <track-element-videorate:src>
             Detected on <smart-mixer-mixer:src>
             Description : serialized events should be pushed in the same order they are received and serialized with buffers. If an event is received after a buffer with timestamp end 'X', it should be pushed right after buffers with timestamp end 'X'

     issue : EOS events that are part of the same pipeline 'operation' should have the same seqnum
             Detected on <streamsynchronizer0:src_1>
             Detected on <aqueue:sink, aqueue:sink>
             Detected on <streamsynchronizer0:src_0>
             Detected on <vqueue:sink, vqueue:sink>
             Detected on <qtdemux1:video_0>
             Detected on <qtdemux1:audio_0, multiqueue1:sink_0, multiqueue1:src_0>
             Detected on <audioconvert1:sink, audioconvert1:src, audioresample1:sink, audioresample1:src, v:sink, v:src>
             Detected on <audioconvert2:sink, audioconvert2:src, audioresample2:sink, audioresample2:src, smart-adder-adder:sink_1>
             Detected on <multiqueue2:sink_0>
             Detected on <qtdemux2:audio_0>
             Detected on <h264parse1:sink>
             Detected on <capsfilter7:sink>
             Detected on <avdec_h264-1:sink>
             Detected on <queue2:sink>
             Detected on <track-element-videoconvert:sink>
             Detected on <deinterlace:sink>
             Detected on <frame_tagger:sink>
             Detected on <track-element-videoscale:sink>
             Detected on <track-element-videorate:sink>
             Detected on <track-element-capsfilter:sink>
             Detected on <videoconvert1:sink>
             Detected on <smart-mixer-mixer:sink_1>
             Description : when events/messages are created from another event/message, they should have their seqnums set to the original event/message seqnum

   warning : received the same caps twice
             Detected on <avdec_h264-1:sink>
             Detected on <capsfilter3:sink>

     issue : SEGMENT events that are part of the same pipeline 'operation' should have the same seqnum
             Detected on <capsfilter3:sink, capsfilter3:src, tee1:sink, tee1:src_0>
             Detected on <audiotee:sink, audiotee:src_0, streamsynchronizer0:sink_1, streamsynchronizer0:src_1, audiotee:sink>
             Detected on <aqueue:sink, aqueue:src, aqueue:sink>
             Detected on <conv:sink, conv:src, resample:sink, resample:src, conv:sink>
             Detected on <audiosink-actual-sink-pulse:sink, audiosink-actual-sink-pulse:sink>
             Detected on <capsfilter0:sink, capsfilter0:src, tee0:sink, tee0:src_0>
             Detected on <streamsynchronizer0:sink_0, streamsynchronizer0:src_0, streamsynchronizer0:sink_0>
             Detected on <vqueue:sink, vqueue:src, vqueue:sink>
             Detected on <conv:sink, conv:src, scale:sink, scale:src, videobalance:sink, videobalance:src, conv2:sink, conv2:src>
             Detected on <gtksink0:sink>
             Description : when events/messages are created from another event/message, they should have their seqnums set to the original event/message seqnum

   warning : EOS received without segment event before
             Detected on <qtdemux2:video_0>
             Detected on <multiqueue2:src_0>
             Detected on <h264parse1:src>
             Detected on <capsfilter7:src>
             Detected on <avdec_h264-1:src>
             Detected on <queue2:src>
             Detected on <track-element-videoconvert:src>
             Detected on <deinterlace:src>
             Detected on <frame_tagger:src>
             Detected on <track-element-videoscale:src>
             Detected on <track-element-videorate:src>
             Detected on <track-element-capsfilter:src>
             Detected on <videoconvert1:src>
             Detected on <smart-mixer-mixer:src>
             Detected on <streamsynchronizer0:src_0>
             Description : A segment event should always be sent before data flow EOS being some kind of data flow, there is no exception in that regard

Issues found: 6
ELEMENT                           %CPU   %TIME   TIME
smart-mixer-mixer                  12.5   51.8    1.40 s
avdec_h264-1                        4.7   19.4    523 ms
capsfilter0                         1.4    5.7    153 ms
track-element-videoconvert          0.5    2.1   57.6 ms
source                              0.4    1.6   44.5 ms
audioresample2                      0.4    1.5   41.4 ms
queue2                              0.3    1.2   32.6 ms
h264parse1                          0.3    1.2   32.1 ms
vconv                               0.3    1.1   29.2 ms
qtdemux1                            0.2    1.0   27.5 ms
bin6                                0.2    0.9   25.1 ms
audiosink                           0.2    0.9   23.4 ms
deinterlace                         0.2    0.8   22.5 ms
tee0                                0.2    0.8   21.2 ms
smart-adder-adder                   0.2    0.8   20.7 ms
aconv                               0.2    0.7   18.4 ms
multiqueue2                         0.2    0.7   18.3 ms
mixing-operation                    0.2    0.7   18.0 ms
source                              0.2    0.7   17.6 ms
capsfilter7                         0.1    0.5   14.6 ms
bin0                                0.1    0.5   14.4 ms
capsfilter3                         0.1    0.4   10.7 ms
internal-sinks                      0.1    0.3   9.22 ms
track-element-videorate             0.1    0.3   8.82 ms
abin                                0.1    0.3   8.52 ms
mixing-operation                    0.1    0.3   8.32 ms
resample                            0.1    0.3   8.28 ms
typefind                            0.1    0.3   8.27 ms
track-element-videoscale            0.1    0.3   8.07 ms
vbin                                0.1    0.3   8.03 ms
tee1                                0.1    0.3   7.41 ms
streamsynchronizer0                 0.1    0.3   6.95 ms
frame_tagger                        0.0    0.2   5.43 ms
video_nlecomposition0               0.0    0.2   5.27 ms
track-element-capsfilter            0.0    0.2   4.69 ms
vqueue                              0.0    0.2   4.37 ms
typefind                            0.0    0.2   4.25 ms
scale                               0.0    0.1   3.51 ms
aqueue                              0.0    0.1   3.31 ms
conv2                               0.0    0.1   3.20 ms
videobalance                        0.0    0.1   3.06 ms
nlesource6                          0.0    0.1   2.56 ms
multiqueue1                         0.0    0.1   2.43 ms
audioresample1                      0.0    0.1   2.02 ms
qtdemux2                            0.0    0.0   1.34 ms
v                                   0.0    0.0   1.29 ms
videorate3                          0.0    0.0   1.14 ms
videorate2                          0.0    0.0    952 us
conv                                0.0    0.0    830 us
audioresample3                      0.0    0.0    520 us
audiotestsrc2                       0.0    0.0    298 us
audioresample0                      0.0    0.0    166 us
gapfilter                           0.0    0.0    132 us
gapfilter                           0.0    0.0    106 us
audio_nlecomposition1               0.0    0.0   69.4 us
src                                 0.0    0.0   54.7 us
nlesource5                          0.0    0.0   51.7 us
src                                 0.0    0.0   43.8 us
uridecodebin1                       0.0    0.0   30.9 us
conv                                0.0    0.0   22.4 us
nlesource4                          0.0    0.0   19.7 us
nlesource7                          0.0    0.0   17.7 us
audioconvert1                       0.0    0.0   13.3 us
audioconvert0                       0.0    0.0   12.3 us
audioconvert2                       0.0    0.0   5.81 us
audiotestsrc3                       0.0    0.0   2.99 us
videoconvert0                       0.0    0.0      0 ns
identity                            0.0    0.0      0 ns
bin8                                0.0    0.0      0 ns
videosrcbin                         0.0    0.0      0 ns
audiosrcbin                         0.0    0.0      0 ns
uridecodebin0                       0.0    0.0      0 ns
gesvideotrack0                      0.0    0.0      0 ns
bin9                                0.0    0.0      0 ns
nlesource9                          0.0    0.0      0 ns
audioconvert3                       0.0    0.0      0 ns
gespipeline0                        0.0    0.0      0 ns
decodebin4                          0.0    0.0      0 ns
audiosink-actual-sink-pulse         0.0    0.0      0 ns
bin7                                0.0    0.0      0 ns
gessmartadder0                      0.0    0.0      0 ns
bin11                               0.0    0.0      0 ns
bin10                               0.0    0.0      0 ns
nlesource8                          0.0    0.0      0 ns
gessmartmixer0                      0.0    0.0      0 ns
current-bin                         0.0    0.0      0 ns
gtksink0                            0.0    0.0      0 ns
decodebin3                          0.0    0.0      0 ns
gesaudiotrack0                      0.0    0.0      0 ns
gestimeline0                        0.0    0.0      0 ns
bin4                                0.0    0.0      0 ns
videoconvert1                       0.0    0.0      0 ns
current-bin                         0.0    0.0      0 ns
identity                            0.0    0.0      0 ns
bin3                                0.0    0.0      0 ns
bin5                                0.0    0.0      0 ns
audiotee                            0.0    0.0      0 ns
gst-launch
[ptv] thiblahute@~/devel/pitivi/1.0-uninstalled/gst-instruments (master|✚4…) $ GST_DEBUG=0 instruments/gst-top-1.0 gst-launch-1.0 uridecodebin name=d uri=file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/YE7VID_720_60_P_MVI_1921.MOV ! queue ! videoconvert ! videoscale ! compositor ! video/x-raw,format=RGBA ! videoconvert ! gtksink d. ! audioconvert ! audioresample ! audiomixer ! audioconvert ! audioresample ! autoaudiosink
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Redistribute latency...
Redistribute latency...
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstPulseSinkClock
Got EOS from element "pipeline0".
Execution ended after 0:00:11.079421779
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...
ELEMENT                            %CPU   %TIME   TIME
autoaudiosink0-actual-sink-pulse     7.3   45.8    811 ms
videoconvert1                        4.3   26.8    475 ms
avdec_h264-0                         1.2    7.6    134 ms
gtksink0                             0.4    2.6   46.2 ms
compositor0                          0.4    2.3   40.2 ms
audioconvert1                        0.3    2.0   35.8 ms
source                               0.3    1.9   34.2 ms
queue0                               0.3    1.7   29.3 ms
audioconvert0                        0.2    1.6   27.8 ms
h264parse0                           0.2    1.4   24.5 ms
autoaudiosink0                       0.2    1.1   18.9 ms
qtdemux0                             0.1    0.9   15.7 ms
capsfilter0                          0.1    0.9   15.7 ms
multiqueue0                          0.1    0.8   14.5 ms
capsfilter1                          0.1    0.7   13.1 ms
videoconvert0                        0.1    0.7   11.8 ms
videoscale0                          0.1    0.4   6.54 ms
audioresample1                       0.1    0.4   6.47 ms
typefind                             0.0    0.3   5.05 ms
audiomixer0                          0.0    0.2   2.82 ms
audioresample0                       0.0    0.1   1.74 ms
d                                    0.0    0.0   5.89 us
decodebin0                           0.0    0.0      0 ns
pipeline0                            0.0    0.0      0 ns

So we can see that for some reason, the compositor is using much more CPU inside the pipeline GES creates, I did not take the time to check why exactly yet, we should at some point but I would not consider that bug as being a blocker for the release tbh, it is more a nice to have optimization as your are trying to play a 60fps h264 stream here...

Also a very interesting test that shows that drawing in Gtk while seeking does not seem to have any effect is to change the content of T3348_benchmarking.scenario to scrub forward seek inside the timeline, like:

description, seek=true, handles-states=true
pause;
add-layer, priority=(int)0;
set-track-restriction-caps, track-type=(string)video, caps=(string)"video/x-raw\,\ framerate\=\(fraction\)25/1";
add-asset, id=(string)file:///home/thiblahute/Videos/pitivi/bugs/samples/YE7VID_720_60_P_MVI_1921.MOV, type=(string)GESUriClip;
add-clip, name=(string)uriclip0, layer-priority=(int)0, asset-id=(string)file:///home/thiblahute/Videos/pitivi/bugs/samples/YE7VID_720_60_P_MVI_1921.MOV, type=(string)GESUriClip, start=(double)0, inpoint=(double)0, duration=(double)11.077733332999999;
commit;
seek, playback-time=0.0, start=position+0.1, repeat="(duration - 0.5)/0.1", flags=accurate+flush
stop, force=true

And see that now the results (for the 2 tests involving GES) look like:

[ptv] thiblahute@~/devel/pitivi/1.0-uninstalled/bugs/T3348  $ ./tests.py
# Checking: pitivi --ges-sample-paths /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348 /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario

Processes average CPU usage:

    Xorg -- 6.790909
    python3 -- 458.428788


# Checking: ges-launch-1.0 --ges-sample-paths file:///home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348 --set-scenario /home/thiblahute/devel/pitivi/1.0-uninstalled/bugs/T3348/T3348_benchmarking.scenario --videosink gtksink

Processes average CPU usage:

    lt-ges-launch-1.0 -- 525.792308
    Xorg -- 3.840385
jeff added a comment.Oct 31 2015, 6:03 PM

It's super awesome that you found part of the perf problem in the GES pipeline, really appreciate that investigation effort! :)

Now, I disagree with one part of the conclusion, the presumption that it is the "only" cause. There's that yes, but the timeline canvas itself is an order of magnitude slower, as far as I can see; otherwise how do you explain the incredible performance boost I've demonstrated in comment #52546 above, where simply hiding the timeline canvas GTK widget solves 90% of the problem? See http://jeff.ecchi.ca/public/pitivi-T3348-gtktimeline-slow-seeks.mov as a quick reminder of what I found.

Furthermore, I see now that the GTK timeline canvas widget also causes performance problem elsewhere, even when seeking is not involved. For example, when toggling the layer controls' menubuttons: http://jeff.ecchi.ca/public/pitivi-T3348-timeline-canvas-vs-popovers-perf.webm

It's not a blocker if you decide it isn't, but it does make Pitivi unusable "for me personally" and I expect complaints & bad press from other users if we have that performance regression shipping with 0.95. Just my 2¢.

Just to add my 2¢ : as an enthousiast, I'm preparing some blog posts to praise the new engine : that performance problem would not fit very well... Besides the last revison was one year ago so waiting some more time would not kill cats I guess ;)

thiblahute added a comment.EditedNov 1 2015, 10:19 AM
In T3348#53364, @jeff wrote:

It's super awesome that you found part of the perf problem in the GES pipeline, really appreciate that investigation effort! :)

Now, I disagree with one part of the conclusion, the presumption that it is the "only" cause. There's that yes, but the timeline canvas itself is an order of magnitude slower, as far as I can see; otherwise how do you explain the incredible performance boost I've demonstrated in comment #52546 above, where simply hiding the timeline canvas GTK widget solves 90% of the problem? See http://jeff.ecchi.ca/public/pitivi-T3348-gtktimeline-slow-seeks.mov as a quick reminder of what I found.

I am just reading the numbers (and I actually ran that benchmark suite many times) and I can say for sure that it is the case on my setup! Could you please run that suite on your PC so that I can read other numbers and hopefully see what you are talking about?

Furthermore, I see now that the GTK timeline canvas widget also causes performance problem elsewhere, even when seeking is not involved. For example, when toggling the layer controls' menubuttons: http://jeff.ecchi.ca/public/pitivi-T3348-timeline-canvas-vs-popovers-perf.webm

This really looks like a perf issue in Gtk itself. I have the impression we might want to tweak the CSS to avoid alpha in the popover menu, cause I would expect some perf while blending issue.

jeff added a comment.Nov 1 2015, 6:16 PM

With tests.py I get ImportError: No module named 'psutil' even though I have python*psutil installed. Python is able to import psutil when outside the environment.

jeff added a comment.EditedNov 2 2015, 2:55 AM

To work around the endless python import issues, I tried rebuilding from scratch with the old environment script, and now I don't get the import errors. However it fails to load the scenario file:

Note that ~/dev/pitivi/ is the only "real" folder;
~/pitivi-git/ is a soft symlink to /mnt/extend/pitivi-git/, and /mnt/extend/pitivi-git/pitivi/ is a symlink to ~/dev/pitivi/

(this is because /mnt/extend is a separate, solid-state drive for performance when building the whole gstreamer stack)

jeff added a comment.EditedNov 2 2015, 9:50 PM

Alright, on my end I get this when running tests.py under the traditional git environment script (not the bundle):

Checking: pitivi --ges-sample-paths /mnt/extend/dev/pitivi /mnt/extend/dev/pitivi/T3348_benchmarking.scenario

Processes average CPU usage:

Xorg -- 18.623129
python3 -- 178.963265

Checking: ges-launch-1.0 --ges-sample-paths file:///mnt/extend/dev/pitivi --set-scenario /mnt/extend/dev/pitivi/T3348_benchmarking.scenario --videosink gtksink

Processes average CPU usage:

lt-ges-launch-1.0 -- 225.311304
Xorg -- 10.155652

Checking: gst-validate-1.0 playbin uri=file:///mnt/extend/dev/pitivi/YE7VID_720_60_P_MVI_1921.MOV video-sink=gtksink

Processes average CPU usage:

gst-validate-1. -- 190.876316
Xorg -- 18.437719

Checking: gst-launch-1.0 uridecodebin name=d uri=file:///mnt/extend/dev/pitivi/YE7VID_720_60_P_MVI_1921.MOV ! queue2 ! videoconvert ! deinterlace ! videoscale ! videorate ! videoconvert ! compositor ! video/x-raw,framerate=30/1 ! tee ! queue ! videoconvert ! videoscale ! videobalance ! videoconvert ! gtksink d. ! audioconvert ! audioresample ! audiomixer ! audioconvert ! audioresample ! queue ! audioconvert ! audioresample ! autoaudiosink

Processes average CPU usage:

gst-launch-1.0 -- 164.425000
Xorg -- 13.850000

I have noticed the following, still:

  1. Perfectly smooth playback with the media library's previewer
  2. Less smooth performance with the timeline and the clip unselected
  3. Very bad playback performance if the clip is selected in the timeline
  4. Perfectly smooth playback (like in #1) if the timeline canvas is hidden through gtk inspector

However… in your scenario used for testing there, you're leaving the default resolution settings instead of using the clip's settings. That's avoiding a big part of the issue!

jeff added a comment.Nov 2 2015, 10:03 PM

This is a scenario file of me creating a blank project, importing the clip, setting the project settings to match, and playing it. Playback is a bit jerkier than the media library's player, but then when I select the clip it becomes a lot jerkier. Again a timeline canvas thing.

thiblahute set git URI to git@github.com:thiblahute/pitivi.git#wip/phab/T3348.

Please jeff give it a try doing:

git phab fetch T3348 && git checkout T3348

(you need git-phab)

thiblahute reopened this task as To Test.Nov 3 2015, 11:55 AM

Please test on master :)

thiblahute reassigned this task from thiblahute to jeghegy.Nov 3 2015, 1:30 PM
jeff added a comment.Nov 4 2015, 4:22 AM

With commit b33905607 it improves one of the performance issues for one particular case, yes (and it's important that this one got solved)... but my issue occurred even without having the clip selected.

So here's the bad news: it still happens. And worse: I just realized now that it's apparently a heisenbug that is unpredictable whether or not it will trigger for a given Pitivi startup/execution. Hence why we've been playing ping-pong for so long on this bug report.

The good news: it's still ostensibly related to the UI, because I can prove as usual that hiding the timeline canvas live makes the issue go away.

Proof that it still happens etc.: with the latest master version, here's what I experienced just now: http://jeff.ecchi.ca/public/pitivi-T3348-still-slow-after-b3390560.MOV
…And right after I filmed that, I closed Pitivi, restarted it, did the exact same thing (new 720p24 project, import métro1.MOV, insert, play) and it didn't happen. And I tried a couple of times and it didn't happen. &?%&%"!!"/$

I have no idea what the heck governs the occurrence of this bug but it exists. It's just a matter of time before it resurfaces again…

jeff added a comment.Nov 4 2015, 4:37 AM

It seems the best way I have found to trigger it so far is this:

  1. Start Pitivi, create a new project with the 720p24 preset
  2. Import "Métro 1.MOV" into the media library, insertEnd to the timeline
  3. Press the Zoom (zoom fit) button. I'm not sure if it's important but it might be.
  4. Play the timeline a bit
  5. Double-click the asset in the media library to preview it in its own window and notice how smooth it is. Only need to play a second or two.
  6. Seek back to the beginning of the timeline (with the ruler), play the timeline a bit
  7. Double-click the asset in the media library, notice how smooth its playback still is

Then repeat step 6 and 7 alternatingly a couple of times (at least 4-5 times?) or infinitely. It seems that the performance gets worse each time, with step #6 starting to have jerky movement etc.

Maybe alt-tabbing between that Pitivi window and this bug report between some of the tries is also making things worse, I don't know. Throwing hypotheses out there at this point...

And as always, no matter how bad performance has become, firing up the GTK Inspector and hiding the timeline widget fixes the issue entirely, the timeline playback becomes butter smooth again.

jeff added a comment.Nov 7 2015, 7:19 PM

Did my latest instructions provide a way for you to finally reproduce this, thiblahute?

thiblahute changed the task status from To Test to In Progress.Nov 8 2015, 1:02 AM
thiblahute claimed this task.
thiblahute lowered the priority of this task from Blocker to Normal.
thiblahute edited projects, added Pitivi 1.0; removed Pitivi 0.95.
thiblahute edited projects, added Pitivi (0.99); removed Pitivi.Apr 17 2016, 1:21 AM
thiblahute moved this task from 0.99 to 1.0 on the Pitivi board.Oct 1 2016, 11:49 PM
thiblahute edited projects, added Pitivi (1.0); removed Pitivi (0.99).