Index rebuild takes 15 minutes with 100% CPU

Afraid I'm not familiar with the "python mmap bug". Zim does not use mmap
calls directly, but they may be used by underlying python libraries.

Have you tried running the commandline index with the "-V" or "-D" switch
to check what zim is doing all this time?

If you have not updated zim, maybe an update of python or filesystem /
kernel related packages could have triggered this ?

Regards,

Jaap

On Tue, Jul 9, 2013 at 1:58 PM, Robert C Watson
<email address hidden>wrote:

> Public bug reported:
>
> Index rebuild proceeds normally till the end where Zim GUI freezes and
> the normal 100% CPU changes from all user to about one third system.
> Repeated 10-second 'strace -c' on the process shows initially only 3
> calls: mmap2, brk, munmap. Soon the brk stops, leaving just mmap2 and
> munmap. (see excerpt below)
>
> First encountered this on doing a Search. Searches now display a few
> hits, then trigger an index rebuild during which both Zim windows are
> frozen. If another notebook is open, its window is NOT frozen. The
> approx. 15min rebuild proceeds as described above. A commandline index
> rebuild with Zim otherwise completely closed (no daemon running)
> exhibits the same behavior. All index rebuilds now take about 15mins.
> All searches now trigger an index rebuild.
>
> Have deleted index.db and rebuilt from scratch numerous times. Same
> behavior.
>
> RAM usage never goes above 200MB. No swap in use. Conky reports Zim
> using only 5-5.5% of memory.
>
> Stats...
> VERSION: 0.56 on Ubuntu 10.04 on 800MHz AMD Athlon processor with 512MB
> memory
> SIZE OF .zim/index.db: 77824 bytes
> HISTORY: Has been working flawlessly for years.
>
> Have fought with this all day including excising vast swaths of pages
> (on a copy of notebook of course) thinking it was due to some non-UTF-8
> pages or bad page names, etc. to no effect. Looks like it's in a tight
> loop allocating and deallocating RAM.
>
> This might be the well documented mmap2 Python bug (see
> http://man7.org/linux/man-pages/man2/mmap.2.html) but why is it only
> being triggered now?
>
> |
> | SAMPLE straces...
> |
>
> 'strace -c' shortly after freeze begins...
>
> root@LX02:/boot/share/NotesArchive/.zim strace -c -p1946
> Process 1946 attached - interrupt to quit
> Process 1946 detached
> % time seconds usecs/call calls errors syscall
> ------ ----------- ----------- --------- --------- ----------------
> 93.18 0.028749 23 1243 munmap
> 6.45 0.001991 3 583 brk
> 0.37 0.000113 0 1244 mmap2
> ------ ----------- ----------- --------- --------- ----------------
> 100.00 0.030853 3070 total
>
>
> 'strace -v' a little later (sample)...
>
> mmap2(NULL, 847872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0xb5e2e000
> munmap(0xb5efd000, 847872) = 0
> mmap2(NULL, 847872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0xb5efd000
> munmap(0xb5e2e000, 847872) = 0
> mmap2(NULL, 847872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0xb5e2e000
> munmap(0xb5efd000, 847872) = 0
> mm...

I suspect you're correct about Python versions. I just need help running down exactly what to change to resolve this.

I installed Python 3.1 awhile back along side Python 2.6.4, then later installed Python 2.7. I've been programming for several decades in lots of languages but new to Python. On encountering many conflicts between the different versions, I uninstalled Python 3.1 but left 2.6 and 2.7. /usr/bin/python is a symlink pointing to the /usr/bin/python2.6 binary which has a size of 930948 and dated 2009-11-19 05:39.

As someone with lots of Python experience, can you recommend a good strategy for support multiple versions of Python on same machine? Since most programs require the older versions, replacing 2.6.4 is not really an option.

Below is the complete output from zim --debug followed immediately by pressing Ctrl-Shft-F for Search, entering '.bashrc' (sans quotes) and ENTER.

All but the last entry of this output, which begins with "'/usr/lib/pymodules...", occurs before the search. The last entry is displayed about 15mins later on successful completion of the search (e.g. more hits are displayed and Zim functions normally.)

In the first 10 seconds of the search, CPU goes to about 95%, all 'user', and a few hits are displayed. That's normal on this machine. CPU usage then changes to about 60% user, 40% system, where it stays till completion. It is during this phase that I took the 'strace -c' samples that pointed to the mmap bug.

 ''root@LX02:~ zim --debug Notes''

''INFO: This is zim 0.56''
''DEBUG: Python version is (2, 6, 5, 'final', 0)''
''DEBUG: Platform is posix''
''DEBUG: Zim revision is:''
'' branch: pyzim-trunk''
'' revision: 533 <email address hidden>''
'' date: 2012-04-02 22:07:22 +0200''
''DEBUG: Not running from a source dir''
''DEBUG: Set XDG_DATA_HOME to /root/.local/share''
''DEBUG: Set XDG_DATA_DIRS to [<Dir: /usr/share/gnome>, <Dir: /usr/local/share>, <Dir: /usr/share>]''
''DEBUG: Set XDG_CONFIG_HOME to /root/.config''
''DEBUG: Set XDG_CONFIG_DIRS to [<Dir: /etc/xdg/xdg-gnome>, <Dir: /etc/xdg>]''
''DEBUG: Set XDG_CACHE_HOME to /root/.cache''
''DEBUG: Running command: gui''
''DEBUG: Loading /root/Notes/notebook.zim''
''DEBUG: Loading /usr/share/zim/manual/notebook.zim''
''DEBUG: Loading /root/Notebooks/Code/notebook.zim''
''DEBUG: Wrote /root/.config/zim/notebooks.list''
''INFO: Starting UnixSocketDaemon''
''DEBUG: Socket address: /tmp/zim-root/daemon-socket''
''DEBUG: Wrote /tmp/zim-root/daemon.pid''
''DEBUG: Sending to daemon: ["ping",[],{}]''

''DEBUG: Daemon replied: "Ack"''
''DEBUG: Sending to daemon: ["vivicate",["zim.gui.GtkInterface","file:///root/Notes"],{"usedaemon":true,"notebook":"file:///root/Notes"}]''

''DEBUG: Child spawned 13540 (u'zim.gui.GtkInterface', u'file:///root/Notes')''
''DEBUG: No such signal: notebook-list-changed''
''DEBUG: Daemon replied: true''
''DEBUG: Sending to daemon: ["relay",[["zim.gui.GtkInterface","file:///root/Notes"],"present",null],{"geometry":null,"fullscreen":null}]''

''DEBUG: Sending to child 13540: ["present",[null],{"geometry":null,"fullscreen":null}]''

''DEBUG: Daemon replied: true''
''DEBUG: ''
''NOTE FOR BUG REPORTS:''
...

Non-markdown paste...

 root@LX02:~ zim --debug Notes
INFO: This is zim 0.56
DEBUG: Python version is (2, 6, 5, 'final', 0)
DEBUG: Platform is posix
DEBUG: Zim revision is:
  branch: pyzim-trunk
  revision: 533 <email address hidden>
  date: 2012-04-02 22:07:22 +0200
DEBUG: Not running from a source dir
DEBUG: Set XDG_DATA_HOME to /root/.local/share
DEBUG: Set XDG_DATA_DIRS to [<Dir: /usr/share/gnome>, <Dir: /usr/local/share>, <Dir: /usr/share>]
DEBUG: Set XDG_CONFIG_HOME to /root/.config
DEBUG: Set XDG_CONFIG_DIRS to [<Dir: /etc/xdg/xdg-gnome>, <Dir: /etc/xdg>]
DEBUG: Set XDG_CACHE_HOME to /root/.cache
DEBUG: Running command: gui
DEBUG: Loading /root/Notes/notebook.zim
DEBUG: Loading /usr/share/zim/manual/notebook.zim
DEBUG: Loading /root/Notebooks/Code/notebook.zim
DEBUG: Wrote /root/.config/zim/notebooks.list
INFO: Starting UnixSocketDaemon
DEBUG: Socket address: /tmp/zim-root/daemon-socket
DEBUG: Wrote /tmp/zim-root/daemon.pid
DEBUG: Sending to daemon: ["ping",[],{}]

DEBUG: Daemon replied: "Ack"
DEBUG: Sending to daemon: ["vivicate",["zim.gui.GtkInterface","file:///root/Notes"],{"usedaemon":true,"notebook":"file:///root/Notes"}]

DEBUG: Child spawned 13540 (u'zim.gui.GtkInterface', u'file:///root/Notes')
DEBUG: No such signal: notebook-list-changed
DEBUG: Daemon replied: true
DEBUG: Sending to daemon: ["relay",[["zim.gui.GtkInterface","file:///root/Notes"],"present",null],{"geometry":null,"fullscreen":null}]

DEBUG: Sending to child 13540: ["present",[null],{"geometry":null,"fullscreen":null}]

DEBUG: Daemon replied: true
DEBUG:
NOTE FOR BUG REPORTS:
 At this point zim has send the command to open a notebook to a
 background process and the current process will no quit.
 If this is the end of your debug output it is probably not useful
 for bug reports. Please close all zim windows, quit the
 zim trayicon (if any), and try again.

 root@LX02:~ DEBUG: Loading /root/.config/zim/preferences.conf
DEBUG: Loaded plugin automount (<AutomountPlugin object at 0x9d593ec (zim+plugins+PluginClass at 0x9ac4170)>)
DEBUG: Gtk version is (2, 20, 1)
DEBUG: Pygtk version is (2, 17, 0)
WARNING: Could not find all icon sizes for the application icon
DEBUG: Loading /root/.config/zim/style.conf
DEBUG: Loading /root/.config/zim/customtools/log-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/todo-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/gnotes-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/archive-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/manual pages (gman)-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/manual pages-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/documents-usercreated-1.desktop
DEBUG: Loading /root/.config/zim/customtools/documents-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/secure notes-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/execute-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/test-usercreated.desktop
DEBUG: Loading /root/.config/zim/customtools/code notebook-usercreated.desktop
DEBUG: Accelmap: /root/.config/zim/accelmap
D...

Having multiple python versions in parallel should not be a problem.
Typically there are versioned executabled like "python26" each of which has
it's own libraries, e.g. "/usr/lib/python26". Using Ubuntu this is all
taken care of by the package manager - I assume debian and other distros do
the same. Just make sure that the "python" symlink goes to 2.6 or 2.7, as
python 3 is not backward compatible, and there are many applications and
scripts that are not yet ported - including zim.

So far no clue what causes the CPU load. Only thing I don't recognize is
the "AddFunction" plugin that is being loaded.

Might also help to see what zim 0.60 does on your system. Not sure if there
is any change related to this problem, as I don't understand the root cause
of the problem, but might be worth the try.

Regards,

Jaap

On Thu, Jul 11, 2013 at 7:24 PM, Robert C Watson <<email address hidden>
> wrote:

> Non-markdown paste...
>
> root@LX02:~ zim --debug Notes
> INFO: This is zim 0.56
> DEBUG: Python version is (2, 6, 5, 'final', 0)
> DEBUG: Platform is posix
> DEBUG: Zim revision is:
> branch: pyzim-trunk
> revision: 533 <email address hidden>
> date: 2012-04-02 22:07:22 +0200
> DEBUG: Not running from a source dir
> DEBUG: Set XDG_DATA_HOME to /root/.local/share
> DEBUG: Set XDG_DATA_DIRS to [<Dir: /usr/share/gnome>, <Dir:
> /usr/local/share>, <Dir: /usr/share>]
> DEBUG: Set XDG_CONFIG_HOME to /root/.config
> DEBUG: Set XDG_CONFIG_DIRS to [<Dir: /etc/xdg/xdg-gnome>, <Dir: /etc/xdg>]
> DEBUG: Set XDG_CACHE_HOME to /root/.cache
> DEBUG: Running command: gui
> DEBUG: Loading /root/Notes/notebook.zim
> DEBUG: Loading /usr/share/zim/manual/notebook.zim
> DEBUG: Loading /root/Notebooks/Code/notebook.zim
> DEBUG: Wrote /root/.config/zim/notebooks.list
> INFO: Starting UnixSocketDaemon
> DEBUG: Socket address: /tmp/zim-root/daemon-socket
> DEBUG: Wrote /tmp/zim-root/daemon.pid
> DEBUG: Sending to daemon: ["ping",[],{}]
>
> DEBUG: Daemon replied: "Ack"
> DEBUG: Sending to daemon:
> ["vivicate",["zim.gui.GtkInterface","file:///root/Notes"],{"usedaemon":true,"notebook":"file:///root/Notes"}]
>
> DEBUG: Child spawned 13540 (u'zim.gui.GtkInterface', u'file:///root/Notes')
> DEBUG: No such signal: notebook-list-changed
> DEBUG: Daemon replied: true
> DEBUG: Sending to daemon:
> ["relay",[["zim.gui.GtkInterface","file:///root/Notes"],"present",null],{"geometry":null,"fullscreen":null}]
>
> DEBUG: Sending to child 13540:
> ["present",[null],{"geometry":null,"fullscreen":null}]
>
> DEBUG: Daemon replied: true
> DEBUG:
> NOTE FOR BUG REPORTS:
> At this point zim has send the command to open a notebook to a
> background process and the current process will no quit.
> If this is the end of your debug output it is probably not useful
> for bug reports. Please close all zim windows, quit the
> zim trayicon (if any), and try again.
>
> root@LX02:~ DEBUG: Loading /root/.config/zim/preferences.conf
> DEBUG: Loaded plugin automount (<AutomountPlugin object at 0x9d593ec
> (zim+plugins+PluginClass at 0x9ac4170)>)
> DEBUG: Gtk version is (2, 20, 1)
> DEBUG: Pygtk version is (2, 17, 0)
> W...

[SOLVED (for me at least)]

Have determined that this was caused by a large, non-Zim text file in an attachment directory. Since the file had the '.txt' extension, Zim was trying to index it instead of ignoring it.

Searching by namespace and process of elimination, located this 536273 byte text file (ChromiumNetInternalsCapture.txt) I'd saved in diagnosing another program. Taking the file out of the Zim directory tree eliminated the problem.

Further diagnosed by isolating and using commands like the following to copy back into Zim successively smaller pieces of the file, then running Update Index...
    head -c196608 /share/ChromiumNetInternalsCapture.txt >ChromiumNetInternalsCapture.txt

CLOCK TIME REQUIRED FOR Update Index (mm:ss)
    -c536273, ~04:20
    -c262144, ~01:10
    -c262100, ~01:00
    -c196608, ~00:30
    -c131072, <00:30
    -c065536, <00:10

Tests were on a machine with an 800MHz AMD Athlon processor and 512MB memory.

This issue may have been resolved in subsequent versions but was still present in 0.59 running on 2.6GHz Intel Celeron CPU with 1.25GB memory. If not practical to resolve, perhaps a warning that .txt files in an attachment directory will be indexed?