Liferea takes approx 2 seconds to act from pressing "next" to displaying anything but white.

[Spider]

I just installed 9.04 to do some testing and I found liferea to be nearly unusable in the current version. I skim a _lot_ of feeds, and it's now stalling for about 2-3 seconds between each time, doing appearantly nothing.

During this time it spikes to the top of the CPU usage ( too short for me to really notice how much) and it generally feels unresponsive.

This is compared to 8.10 where it would fsync() storm and eat ram, but at least was responsive. Now it just feels like swimming in molasses.

Description: Ubuntu jaunty (development branch)
Release: 9.04
liferea:
  Installed: 1.4.23-0ubuntu2
  Candidate: 1.4.23-0ubuntu2
  Version table:
 *** 1.4.23-0ubuntu2 0
        500 http://se.archive.ubuntu.com jaunty/main Packages
        100 /var/lib/dpkg/status

[Dimitrios Symeonidis (azimout)]

importance=low
however, I couldn't reproduce this here. Note that Jaunty ships with 1.4.26 now, can you please check if this is fixed for you? Thank you!

[Spider (spider-alternating)]

That still happens in the current version, also there's a HUGE lockup-like wait if you hit "reload all feeds" on this machine. It basically stands still for about a minute ( Metacity thinks it has hanged and will offer to force it to close for you)

As for me, I have ~90 active feeds that I follow, to give an impression on the scale of things where I see a horrible slowdown.

[Dimitrios Symeonidis (azimout)]

Spider, I have 81 feeds. I don't have this problem.
When you press "Update All", do you see the feeds being parsed one-by-one in the status bar?
Also, what is your hardware configuration? (cpu, ram)
Finally, can you check if the lock-up happens due to high disk activity? In that case, this might be a duplicate of bug #335471

[Spider (spider-alternating)]

Hardware, Core2 duo ( clocked at 2.4GHz) with 6GB RAM, system on a sata-II disk.
from this vmstat 1 log it's fairly obvious where I hit the "load all" button, but that's not a terribly high load either.

if I run liferea with the --debug-all flag The whole thing slows down so much that it's hard to notice what would be the cause based on the output.

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r b swpd free buff cache si so bi bo in cs us sy id wa
 1 0 0 2457988 171952 2628984 0 0 65 18 940 666 37 3 58 1
 0 0 0 2457972 171952 2628984 0 0 0 0 113 105 0 0 100 0
 0 0 0 2457972 171952 2628984 0 0 0 0 144 166 0 0 100 0
 0 0 0 2457972 171952 2628984 0 0 0 0 220 1018 1 0 99 0
 0 0 0 2457972 171956 2628980 0 0 0 56 233 1468 3 0 97 1
 0 0 0 2457972 171956 2628984 0 0 0 0 118 122 1 0 99 0
 0 0 0 2457972 171956 2628984 0 0 0 0 132 149 0 0 100 0
 0 0 0 2457972 171956 2628984 0 0 0 0 202 1330 0 0 100 0
 0 1 0 2457972 172024 2628932 0 0 0 540 476 837 0 0 69 30
 2 1 0 2457972 172112 2628928 0 0 0 708 482 867 0 1 59 40
 0 1 0 2457772 172220 2628900 0 0 0 632 441 431 1 0 61 39
 0 1 0 2457624 172272 2628956 0 0 0 700 446 382 1 0 63 36
 0 0 0 2457600 172384 2628904 0 0 0 700 543 922 0 1 52 47
 0 1 0 2457600 172524 2628880 0 0 0 752 436 409 0 0 64 35
 0 1 0 2457400 172640 2628896 0 0 0 684 471 506 0 1 63 35
 0 1 0 2457352 172788 2628876 0 0 0 704 419 406 0 1 67 33
 0 1 0 2457104 172932 2628888 0 0 0 680 394 405 0 1 61 37
 0 1 0 2456980 173092 2628848 0 0 0 684 466 412 1 0 61 37
 0 1 0 2456756 173244 2628880 0 0 0 680 428 427 0 0 55 44
 0 1 0 2456532 173384 2628896 0 0 0 692 429 387 0 0 65 35
 0 1 0 2456484 173508 2628892 0 0 0 596 421 538 2 0 58 40
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r b swpd free buff cache si so bi bo in cs us sy id wa
 1 1 0 2456384 173636 2628896 0 0 0 640 376 332 1 1 60 39
 0 1 0 2456236 173744 2628916 0 0 0 692 457 437 0 0 71 28
 0 1 0 2456036 173868 2628876 0 0 0 688 488 13070 2 2 60 36
 0 0 0 2455772 174000 2628904 0 0 0 624 641 3986 2 0 56 42
 0 0 0 2455500 174056 2628952 0 0 16 264 550 1570 15 2 70 13
 2 0 0 2455500 174056 2629000 0 0 0 0 294 887 0 0 99 0
 0 1 0 2455500 174092 2628964 0 0 0 232 388 951 2 0 91 8
 1 0 0 2439700 174216 2644316 0 0 8 796 573 555 15 1 45 38
 0 0 0 2455344 174216 2629008 0 0 0 16004 235 190 1 1 99 0
 0 1 0 2455360 174252 2628972 0 0 0 240 334 367 1 0 91 8
 0 0 0 2455360 174296 2629016 0...

[Spider (spider-alternating)]

GUI: feed list selection changed to "Slashdot"
GUI: new selected node: Slashdot
GUI: loading item list with node "Slashdot"
GUI: Setting item list visibility mode: 0
GUI: reloading item list with node "Slashdot"
GUI: itemlist merge took 0,019s
GUI: item list selection changed to "Vista Post-SP2 Is the Safest OS On the Planet"
GUI: set read status took 0,611s
GUI: itemlist selection took 0,647s
GUI: item list selection changed to "Android 1.5 SDK Is Released"
GUI: set read status took 0,531s
GUI: itemlist selection took 0,540s
GUI: item list selection changed to "College Police Think Using Linux Is Suspicious Behavior"
GUI: set read status took 0,548s
GUI: itemlist selection took 0,557s
GUI: item list selection changed to "NASA Taking Ethernet Into Deeper Space"
GUI: set read status took 0,587s
GUI: itemlist selection took 0,596s
GUI: item list selection changed to "Microsoft Won't Vouch For Linux"
GUI: set read status took 0,741s
GUI: itemlist selection took 0,750s

--debug-gui shows some interesting things.

[Spider (spider-alternating)]

And here we get to the behaviour issues that I'm bothered by :

GUI: feed list selection changed to "..GStreamer"
GUI: new selected node: ..GStreamer
GUI: loading item list with node "..GStreamer"
GUI: Setting item list visibility mode: 0
GUI: reloading item list with node "..GStreamer"
GUI: itemlist merge took 0,025s
GUI: item list selection changed to "Web (Django) Developer opportunity"
GUI: set read status took 0,997s
GUI: itemlist selection took 1,005s
GUI: item list selection changed to "Music"
GUI: set read status took 1,719s
GUI: set read status took 2,322s
GUI: set read status took 3,930s
GUI: itemlist selection took 6,609s

Otherwise unloaded system

[Dimitrios Symeonidis (azimout)]

ok, setting back to new
might be the sqlite...

[Spider (spider-alternating)]

Here's another gui-debug log output that shows some interesting behaviours:

Otherwise unloaded system ( an idle browser with a blank page, a music player and IM client running at the same time. Virtually nothing)

GUI: reloading item list with node "grinding.be"
GUI: itemlist merge took 0,033s
GUI: item list selection changed to "How six people in Moldova possibly saved an election"
GUI: set read status took 1,912s
GUI: itemlist selection took 1,958s
GUI: Fatal: no node with id "ttmgyjx" found!
GUI: feed list selection changed to "BB: Gadgets"
GUI: new selected node: BB: Gadgets
GUI: loading item list with node "BB: Gadgets"
GUI: Setting item list visibility mode: 0
GUI: reloading item list with node "BB: Gadgets"
GUI: itemlist merge took 0,052s
GUI: item list selection changed to "Gizmodo mounted on maple blocks, sounds great"
GUI: set read status took 1,748s
GUI: itemlist selection took 2,650s
GUI: item list selection changed to "Stealthy Ninja Jacket is Magical*"
GUI: set read status took 1,757s
GUI: itemlist selection took 1,765s
GUI: item list selection changed to "The White Stripes reimagine two classic "toy" cameras into collector's items"
GUI: set read status took 1,353s
GUI: itemlist selection took 1,362s
GUI: item list selection changed to "FamilyMap: Track your family using the same technology the government is using to track them"
GUI: set read status took 1,916s
GUI: itemlist selection took 1,925s
GUI: item list selection changed to "Time Travel Cheatsheat"
GUI: set read status took 1,638s
GUI: itemlist selection took 2,463s
GUI: item list selection changed to "CycleKarting, hand-built vintage race cars"
GUI: set read status took 1,916s
GUI: itemlist selection took 1,925s
GUI: item list selection changed to "Gator Guard is a scareduck"
GUI: set read status took 1,435s
GUI: itemlist selection took 1,443s
GUI: item list selection changed to "Today on Offworld"
GUI: set read status took 1,343s
GUI: itemlist selection took 1,351s
GUI: feed list selection changed to "Planets"
GUI: new selected node: Planets
GUI: loading item list with node "Planets"
GUI: feed list selection changed to "..GNOME"
GUI: new selected node: ..GNOME
GUI: loading item list with node "..GNOME"
GUI: Setting item list visibility mode: 0
GUI: reloading item list with node "..GNOME"
GUI: itemlist merge took 0,048s
GUI: item list selection changed to "(null)"
GUI: set read status took 1,411s
GUI: itemlist selection took 1,449s
GUI: feed list selection changed to "..Ubuntu"
GUI: new selected node: ..Ubuntu
GUI: loading item list with node "..Ubuntu"
GUI: Setting item list visibility mode: 0
GUI: reloading item list with node "..Ubuntu"
GUI: itemlist merge took 0,039s
GUI: item list selection changed to "Guy Van Sanden: Controverses about Jaunty's new notification system"
GUI: set read status took 0,568s
GUI: itemlist selection took 0,612s
GUI: item list selection changed to "Launchpad News: Karma — where did mine go?"
GUI: set read status took 0,556s
GUI: itemlist selection took 0,565s
GUI: item list selection changed to "Thierry Carrez: How to find Java classes in the distribution"
GUI: set read status took 0,579s
GUI: itemlist selection took 0,587s

[Rodrigo Linfati (rlinfati)]

repro

ubuntu 9.04 + ext4

liferea make a log of fsync...

[Rodrigo Linfati (rlinfati)]

i make a very ugly hack to fix this.

rlinfati@virtu:~$ uname -a
Linux virtu 2.6.28-11-generic #42-Ubuntu SMP Fri Apr 17 01:57:59 UTC 2009 i686 GNU/Linux
rlinfati@virtu:~$ mount |grep ext4
/dev/sda2 on / type ext4 (rw,relatime,errors=remount-ro)

On /usr/src/libfsync/ i make the libfsync.c file
**** libfsync.c ****
int fsync (int fd) {
 return 0;
}
******************
and compile with "gcc -Wall libfsync.c -o libfsync.so -shared -fPIC -Wl,-soname,libfsync.so"

and, in the 2nd line of /usr/bin/liferea put "export LD_PRELOAD=/usr/src/libfsync/libfsync.so"

and fixed!

NOW.... please remove excesive fsync of liferea to make a real fix!

Thanks!

[Rodrigo Linfati (rlinfati)]

liferea + ext4

[Emilio Pozuelo Monfort (pochu)]

Rodrigo Linfati wrote:
> NOW.... please remove excesive fsync of liferea to make a real fix!

We (upstream) are aware of the performance problems, and will be seriously
looking at them for the 1.8 series (we are going to release 1.6 very soon).

[Shane Kerr (shane-time-travellers)]

I just tried the liferea 1.5.15 release (built from source) and I still see the same performance problems. So 1.6 is not likely to help. It would be very nice if the performance improvements (whatever they are) could get in before the Koala window closes, otherwise it'll be a full year where liferea is basically unusable on Ubuntu. :(

[abhiroopb (abhiroopb241088)]

That is a long wait, for a relatively important piece of software!

[abhiroopb (abhiroopb241088)]

Rodrigo, your fix worked wonders I can use liferea now :). Many thanks. Just concerned if there any adverse effects to this? As I have no idea what this did.

[Spider (spider-alternating)]

The "fix" he does is basically turning liferea into a bit more fragile.

What it does is turn the fsync() call into a no-op (no operation) , basically making it do nothing.
On Linux, a call to fsync will in general (ext3/4, jfs) flush all applications unwritten data to disk, causing a momentary stall as it waits to return from this. Basically the slowdown you see is the program repeatedly (far too often, several times per second) asking for it's data to be written to disk, and waiting around for the system to make sure that it's there.

For something like liferea that's completely bogus behaviour.

[abhiroopb (abhiroopb241088)]

Thats interesting. I can see that this applies to ext4 (as its new), but I was using liferea in ext3 and it was fine. How would that be explained?

[Spider (spider-alternating)]

Easiest way is to simply run a profiler on it and see ( oprofile works ) Not sure how well implemented the support for it is in Ubuntu as I have Gentoo-based systems for development rather.