Re: Vector Source and QT GUI Time Sink causes performance drop

[Marcus Müller]

by the way, there's no GNU Radio at all in this profile – are you sure
you ran exactly the `perf record -ag python path/to/..` as recommended?

On 11.01.21 16:53, Mariusz Pluciński wrote:
> Hi,
> 
> Thanks for the hint, I didn't know about this method of profiling :). I
> did as you requested and it seems that it spends quite a lot of time in
> Qt, namely in *gray_render_line* and *gray_render_scanline* functions.
> If my understanding is correct, this time is spent in Qt itself, not in
> the underlying graphics stack. Which would mean that either GNU Radio
> generates too many rendering requests or this version of Qt is buggy.
> What do you think?
> 
> Full output:
> 
> +   33,04%    32,32%  python3          libQt5Gui.so.5                  
>                  [.] gray_render_line
> +   23,39%    22,70%  python3          libQt5Gui.so.5                  
>                  [.] gray_render_scanline
> +   11,10%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] secondary_startup_64
> +   11,10%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] cpu_startup_entry
> +   11,08%     0,02%  swapper          [kernel.kallsyms]                
>                 [k] do_idle
> +   10,59%     0,01%  swapper          [kernel.kallsyms]                
>                 [k] call_cpuidle
> +   10,58%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] cpuidle_enter
> +   10,56%     0,04%  swapper          [kernel.kallsyms]                
>                 [k] cpuidle_enter_state
> +   10,08%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] start_secondary
> +    6,50%     0,02%  swapper          [kernel.kallsyms]                
>                 [k] acpi_idle_enter
> +    6,47%     6,20%  swapper          [kernel.kallsyms]                
>                 [k] acpi_processor_ffh_cstate_enter
> +    6,46%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_idle_do_entry
> +    4,26%     0,00%  python3          [unknown]                        
>                 [k] 0x0000000000000004
> +    4,15%     0,35%  python3          libc-2.31.so
> <http://libc-2.31.so>                                      [.] __sched_yield
> +    4,04%     0,01%  swapper          [kernel.kallsyms]                
>                 [k] acpi_idle_enter_bm
> +    3,57%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] ret_from_intr
> +    3,57%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] do_IRQ
> +    3,56%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] handle_fasteoi_irq
> +    3,56%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] handle_irq_event
> +    3,56%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] handle_irq_event_percpu
> +    3,48%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] __handle_irq_event_percpu
> +    3,37%     0,14%  python3          [kernel.kallsyms]                
>                 [k] entry_SYSCALL_64_after_hwframe
> +    3,18%     0,08%  python3          [kernel.kallsyms]                
>                 [k] do_syscall_64
> +    2,87%     0,06%  python3          [kernel.kallsyms]                
>                 [k] __x64_sys_sched_yield
> +    2,65%     0,08%  python3          [kernel.kallsyms]                
>                 [k] do_sched_yield
> +    2,54%     0,07%  python3          [kernel.kallsyms]                
>                 [k] schedule
> +    2,30%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_irq
> +    2,29%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_ev_sci_xrupt_handler
> +    2,27%     0,42%  python3          [kernel.kallsyms]                
>                 [k] __sched_text_start
> +    2,26%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_ev_gpe_detect
> +    2,23%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_ev_detect_gpe
> +    2,01%     0,04%  WebExtensions    [unknown]                        
>                 [.] 0000000000000000
> +    1,96%     0,01%  swapper          [kernel.kallsyms]                
>                 [k] acpi_hw_read
> +    1,94%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] acpi_hw_read_port
> +    1,93%     1,93%  swapper          [kernel.kallsyms]                
>                 [k] acpi_os_read_port
> +    1,50%     0,43%  python3          [kernel.kallsyms]                
>                 [k] pick_next_task_fair
> +    1,10%     0,00%  WebExtensions    [unknown]                        
>                 [.] 0xf8894804751efe83
> +    1,10%     0,00%  WebExtensions    libxul.so                        
>                 [.] 0x00007fe0e92a31f0
> +    1,02%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] x86_64_start_kernel
> +    1,02%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] x86_64_start_reservations
> +    1,02%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] start_kernel
> +    1,02%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] arch_call_rest_init
> +    1,02%     0,00%  swapper          [kernel.kallsyms]                
>                 [k] rest_init
> +    1,00%     1,00%  python3          libQt5Gui.so.5                  
>                  [.] gray_set_cell
> 
> It seems that 50% of the time is spend in libQt5Gui.so. As far as I
> understand the output, "swapper" is a kernel process, so it may or may
> not be related.
> 
> I'll try to build latest Qt separately later and link GNU Radio against
> it, and see what happens :>
> 
> Best Regards,
> Mariusz Plucinski
> 
> 
> Am Mo., 11. Jan. 2021 um 12:29 Uhr schrieb Marcus Müller
> <mueller@kit.edu <mailto:mueller@kit.edu>>:
> 
>     Hi,
> 
>     I'm on the run, else I'd start a Ubuntu VM myself, but:
> 
>     sudo apt install linux-tools
>     sudo sysctl -w kernel.perf_event_paranoid=-1
> 
>     perf record -ag python3 /path/to/your/flowgraph.py
> 
>     run for a couple of seconds, close.
> 
>     Afterwards,
> 
>     perf report
> 
>     will hopefully show you a percentage of "of the times we looked, the
>     CPU
>     was busy with this and that function".
> 
>     Best regards,
>     Marcus
> 
>     On 11/01/2021 12.15, Mariusz Pluciński wrote:
>     > Hi,
>     >
>     > I tested on a different machine of mine (Fedora 32, GNU Radio
>     3.8.2) and
>     > the problem does not occur there.
>     > This suggests that the problem is somehow specific to this Ubuntu
>     > system, but not to a specific build of GNU Radio (nor Python, it
>     occurs
>     > with both 3.8 and 3.9). Since this looks more like a GUI problem than
>     > signal processing itself, I'm wondering if it may be related to
>     the Qt
>     > version there - 5.12.8. The machine it works correctly on has 5.14.2
>     > installed.
>     >
>     > Attached the test file. It works fine on my Fedora but very slow (in
>     > terms of GUI responsiveness) on my Ubuntu. Would be great if somebody
>     > could point me in a right direction of what else I can check.
>     >
>     > Mit freundlichen Grüßen
>     > Mariusz Plucinski
>     >
>     >
>     > Am So., 10. Jan. 2021 um 18:41 Uhr schrieb Jeff Long
>     > <willcode4@gmail.com <mailto:willcode4@gmail.com>
>     <mailto:willcode4@gmail.com <mailto:willcode4@gmail.com>>>:
>     >
>     >     I was using 2MS/s, tested with 3.8 and master (which should be
>     close
>     >     enough to 3.9). Nothing comes to mind. You could post a GRC file,
>     >     just in case there's a misunderstanding of how something works.
>     >
>     >     On Sun, Jan 10, 2021 at 10:00 AM Mariusz Pluciński
>     >     <plucinski.mariusz@gmail.com
>     <mailto:plucinski.mariusz@gmail.com>
>     <mailto:plucinski.mariusz@gmail.com
>     <mailto:plucinski.mariusz@gmail.com>>>
>     >     wrote:
>     >
>     >         Thank you for trying this. It assures me that it's something
>     >         wrong either in my project or in my configuration.
>     >
>     >         I also tried to build GNU Radio from source (3.9.0 RC2 from
>     >         git), but the problem also occurs there.
>     >
>     >         What do you mean by "reasonable sample rate"? I'm trying with
>     >         very low values like 300 (in both throttler and time sink) and
>     >         the problem still occurs.
>     >
>     >         In the new build, there seems to be a small delay before the
>     >         data appear on the chart. Up to this moment, the window is
>     >         reponsive, but as soon as the green lines appear, it
>     becomes not
>     >         responsive again - best visible when trying to resize the
>     window.
>     >
>     >         Is there anything else I can check?
>     >
>     >         Mit freundlichen Grüßen
>     >         Mariusz Plucinski
>     >
>     >
>     >         Am So., 10. Jan. 2021 um 02:55 Uhr schrieb Jeff Long
>     >         <willcode4@gmail.com <mailto:willcode4@gmail.com>
>     <mailto:willcode4@gmail.com <mailto:willcode4@gmail.com>>>:
>     >
>     >             I gave this a try, adding Vector Source -> Throttle -> QT
>     >             GUI Time Sink to a flowgraph. Performance is fine at 2MS/s
>     >             on an older laptop. Make sure that the Throttle is
>     being set
>     >             to a reasonable sample rate.
>     >
>     >             On Sat, Jan 9, 2021 at 6:35 PM Mariusz Pluciński
>     >             <plucinski.mariusz@gmail.com
>     <mailto:plucinski.mariusz@gmail.com>
>     >             <mailto:plucinski.mariusz@gmail.com
>     <mailto:plucinski.mariusz@gmail.com>>> wrote:
>     >
>     >                 Hi,
>     >
>     >                 Thanks for the answers. Unfortunately, I already tried
>     >                 this before (forgot to mention) and it doesn't change
>     >                 anything in this weird behavior of the GUI window.
>     >                 It also doesn't help to have a hardware source and/or
>     >                 sink in the flow (tried with Audio Sink and osmocom
>     >                 Sink/Source); as soon as I enable both Vector
>     Source and
>     >                 QT GUI Time Sink at the same time (anywhere in the
>     >                 flow), everything becomes unusably slow.
>     >
>     >                 I also tried to add a separate path Null Source ->
>     >                 Throttle -> Null Sink (as seen somewhere in the Wiki),
>     >                 but this also didn't help. Changing sample rate of the
>     >                 throttle also doesn't seem to change anything.
>     >
>     >                 Is there any way I can diagnose this issue?
>     >
>     >                 Regards,
>     >                 Mariusz
>     >
>     >                 Am Sa., 9. Jan. 2021 um 23:47 Uhr schrieb Derek Kozel
>     >                 <derek@bitstovolts.com
>     <mailto:derek@bitstovolts.com> <mailto:derek@bitstovolts.com
>     <mailto:derek@bitstovolts.com>>>:
>     >
>     >                     Hi Mariusz,
>     >
>     >                     The main issue here is that you're missing a
>     >                     Throttle block in your flowgraph. You have no
>     >                     Hardware block in the flowgraph, it is pure
>     >                     simulation. GNU Radio will try to run the
>     processing
>     >                     as fast as possible, using 100% of available
>     CPU. A
>     >                     Throttle block limits the simulation speed to
>     >                     approximately realtime (to the set sample rate per
>     >                     second).
>     >
>     >                     A hardware source or sink will have a real,
>     physical
>     >                     clock and will restrict the number of samples
>     >                     produced (Source) or consumed (Sink) and the other
>     >                     blocks will not be able to run at infinite speed
>     >                     (using all the CPU).
>     >
>     >                     I'm curious why that would work better with a
>     >                     different non-hardware source rather than the
>     Vector
>     >                     Source, but the recommended fix is
>     straightforward.
>     >
>     >                     Regards,
>     >                     Derek
>     >
>     >
>     >
>     >
>     >                 Am Sa., 9. Jan. 2021 um 23:49 Uhr schrieb Ron Economos
>     >                 <w6rz@comcast.net <mailto:w6rz@comcast.net>
>     <mailto:w6rz@comcast.net <mailto:w6rz@comcast.net>>>:
>     >
>     >                     It's telling you what's wrong.
>     >
>     >                      >>> Warning: This flow graph may not have flow
>     >                     control: no audio or RF hardware blocks found.
>     Add a
>     >                     Misc->Throttle block to your flow graph to
>     avoid CPU
>     >                     congestion.
>     >
>     >                     Add a Throttle block between the Vector Source and
>     >                     QT GUI Time Sink blocks.
>     >
>     >                     Ron
>     >
>     >
>     >                     On 1/9/21 14:32, Mariusz Pluciński wrote:
>     >>                     Hello everybody,
>     >>
>     >>                     I'm quite new to GNU Radio (and to signal
>     >>                     processing as well), but I did a few successful
>     >>                     experimens. But now, I encountered a weird
>     >>                     behavior, namely:
>     >>
>     >>                     Every flowgraph including Vector Source and
>     QT GUI
>     >>                     Time Sink conencted (regardless if directly or
>     >>                     with intermediate steps) causes huge performance
>     >>                     degradation. CPU usage jumps to 100% of a core,
>     >>                     window takes a few seconds to refresh, GUI
>     becomes
>     >>                     almost unusable.
>     >>
>     >>                     Everything works well if I use any different
>     >>                     source, .e.g. Signal Source or osmocom Source.
>     >>                     Everything works well if I use any different
>     sink,
>     >>                     e.g. Audio Sink or QT GUI Frequency Sink.
>     >>
>     >>                     It's just this specific combination that causes
>     >>                     the issue. Drastically reducing the number of
>     >>                     points in the Time Sink helps, but at the cost of
>     >>                     the output becoming useless.
>     >>
>     >>                     To reproduce the problem, it's enough to do the
>     >>                     following in GNU Radio Companion:
>     >>                     1. Create an empty flow graph
>     >>                     2. Add "Vector Source"
>     >>                     3. Change "Vector" parameter to "(0, 0, 0, 1)"
>     >>                     4. Add "QT GUI Time Sink"
>     >>                     5. Connect both blocks
>     >>                     6. Run
>     >>
>     >>                     Am I doing something wrong here?
>     >>
>     >>                     (in case it's necessary, my ultimate goal here is
>     >>                     to use the vector source as a source of bits to
>     >>                     modulate a square wave; the output will later be
>     >>                     transmitted out, but first, I'd like to see it in
>     >>                     the Time Sink)
>     >>
>     >>                     I'm using GNU Radio 3.8.1.0 on Ubuntu 20.04.
>     >>
>     >>                     Best Regards,
>     >>                     Mariusz Plucinski
>     >
>