Consistent over usage of CPU

[GreenLunar]

Liferea, at some point of a session, start to consistently consumes 100% of one core of my CPU. Using Liferea 1.11.6 under Salix 14.1 (32-bit) on i686 Pentium(R) Dual-Core CPU E5200 @ 2.50GHz.

This has occurred to me in previous version of Liferea. I know the information I provide here is not enough.

[genodeftest]

If this happens again, can you please

1. try to remember what you did before it happened. A reliable reproducer would be helpful.
2. attach a debugger to liferea and get a backtrace. Make sure you have debug symbols for liferea (read the output of gdb). It should work like this: gdb /usr/local/bin/liferea -p PID where PID is the process identifier of your liferea instance running at 100% CPU. Gdb should now stop liferea. If not, press Ctrl+C inside gdb. After that run these commands inside gdb:

set logging on liferea-busy-loop.txt
t a a bt full
set logging off

You should then have a file liferea-busy-loop.txt with a huge backtrace. Please upload it somewhere after making sure it contains no personal data.

[GreenLunar]

@genodeftest, I have made a log with liferea --debug-all.

@lwindolf, did you receive my email with a log? (was sent on March 2nd)

[lwindolf]

@GreenLunar Nope. It might be that I missed it. Can you resend it?

[GreenLunar]

Sent under title [Liferea] Consistent over usage of CPU #271

[lefou]

Same behaviour here with Liferea 1.12.3 on Gentoo Linux.

[lwindolf]

A screenshot of

sudo perf top -a -p $(pgrep liferea)

would be great to see which symbol is eating up CPU

[lefou]

Output of sudo perf top -a -p $(pgrep liferea)

   PerfTop:    4096 irqs/sec  kernel: 0.0%  exact: 100.0% [4000Hz cycles:ppp],  (target_pid: 5259)
------------------------------------------------------------------------------------------------------------

    53.99%  liferea                  [.] feedlist_unread_scan
    38.03%  liferea                  [.] node_is_ancestor
     5.04%  libglib-2.0.so.0.5200.3  [.] g_slist_find
     1.16%  liferea                  [.] vfolder_get_node_type
     0.98%  liferea                  [.] icon_get
     0.74%  liferea                  [.] g_slist_find@plt
     0.01%  [kernel]                 [k] intel_thermal_interrupt
     0.00%  [kernel]                 [k] i8042_interrupt
     0.00%  [kernel]                 [k] inode_init_always
     0.00%  [kernel]                 [k] update_curr
     0.00%  [unknown]                [k] 0x000055ace7faf400
     0.00%  [kernel]                 [.] native_irq_return_iret
     0.00%  [kernel]                 [k] check_preemption_disabled
     0.00%  [kernel]                 [k] _raw_spin_trylock
     0.00%  [kernel]                 [k] switch_to_thread_stack
     0.00%  [kernel]                 [k] debug_smp_processor_id
     0.00%  [unknown]                [k] 0x000055ace7fb7969
     0.00%  [kernel]                 [k] lapic_next_deadline
     0.00%  [kernel]                 [k] update_wall_time
     0.00%  [kernel]                 [k] __intel_pmu_enable_all.constprop.10
     0.00%  [kernel]                 [k] task_tick_fair
     0.00%  [kernel]                 [k] queued_spin_lock_slowpath
     0.00%  [unknown]                [k] 0x000055ace7fb7960
     0.00%  [kernel]                 [k] rcu_cblist_dequeue
     0.00%  [kernel]                 [k] therm_throt_process
     0.00%  [kernel]                 [k] e1000_irq_enable
     0.00%  [kernel]                 [k] update_vsyscall
     0.00%  [kernel]                 [k] notifier_call_chain
     0.00%  libc-2.26.so             [.] __GI___libc_open
     0.00%  [kernel]                 [k] swapgs_restore_regs_and_return_to_usermode
     0.00%  [kernel]                 [k] trigger_load_balance
     0.00%  [kernel]                 [k] __rcu_read_lock
     0.00%  [kvm]                    [k] pvclock_gtod_notify
     0.00%  [unknown]                [k] 0x000055ace7fb796e
     0.00%  [kernel]                 [k] smp_call_function_single_interrupt
     0.00%  [kernel]                 [k] __update_load_avg_cfs_rq.isra.3
     0.00%  [kernel]                 [k] rcu_segcblist_ready_cbs
     0.00%  [kernel]                 [k] native_sched_clock
     0.00%  [kernel]                 [k] ret_from_intr
     0.00%  [unknown]                [k] 0x000055ace7faf3ae
     0.00%  [kernel]                 [k] run_timer_softirq

[lwindolf]

That helps a lot. It looks like you've used the "next unread" feature and it is stuck in an endless loop. The method calls itself recursively to do a 2 pass scan keeping the scan state in a static var. So it could be a logic issue or a race condition on the static var...

[lefou]

Yes, I almost always use "next unread", but not the one linked to Ctrl+N, but the simple N (which requires focus on the feed entry list). If I press N immediately after a fresh start of Liferea, it is very likely to run into the issue. This might help to reproduce the issue.

[lwindolf]

While I fail to reproduce it, I think the recursion has to go. The logic is just too complex. This is old 2006/2008 code and nowadays I'm like 2% smarter not to do recursion when not warranted :-)

Plan is to

• Ad-hoc convert feed list to flat ordered list of feeds with unread counts including the selected node/folder.
• Do a 2-pass on this list, first starting from the selected node and then from start to selected node
• Try to select the node id found

Reimplementing like this should prevent any loop and race.

[lefou]

Maybe of interest. The high CPU issue occurs after pressing N and there are no visibly unread messages in the left tree. But in the status bar on the right side, it says "2 unread". Looks like there is some mismatch between what I can spot in the tree and the status counter.

[Leiaz]

@lefou The 2 unread looks like issue #646 which was fixed some time ago.

[lefou]

@Leiaz Thanks for the pointer. I'm on 1.12.3 and will test 1.12.4 now. I'll report back.

[lefou]

Looks like, it was #646 which bugged me and 1.12.4 fixed it. Thank you. Although I had the 100% CPU issue long before 1.12.3.

[lwindolf]

@lefou Thanks for the retest!