search

cpbotha / nvpy

Simplenote syncing note-taking application, inspired by Notational Velocity and ResophNotes, but uglier and cross-platformerer.
Other
849 stars 114 forks source link

nvpy freezing hard when typing intial characters in search on acct with over 1500 notes, makes searching very difficult. #233

Open wrathofthomas opened 10 months ago

wrathofthomas commented 10 months ago

As soon as I start to type anything or remove any characters in the search box. It starts searching immediately and nvpy freezes for up to 30s with the rest of the ui being unusable until the search is complete. The first character is the worst, it freezes until the first character has been "searched", and there is another lesser delay on the second character, and less of a delay but still slow for the third. After about the third character, it speeds up significantly with almost no lag(less to search at that point). So it takes up to a minute to even type the word "test" in the search box, with the application trying to search again every time a character is typed. Gstyles or regexp both have this issue.

Pasting a full word or partial word above three characters is much faster, almost immediately gives results. Pasting "test" searches test with no freeze or lag. Have installed and reinstalled the latest version, deleted notes and done full resync, replaced cfg, etc. Anything I am missing to make this faster? I don't remember this being the case a few versions back, and I had a similar volume of notes.

If there is no easy fix, I propose a 1 sec delay to be added after characters start to be modified in the search box, so that by the time nvpy starts to search, there are likely already 3+ characters and no hang up ever begins.

Thanks!

yuuki0xff commented 10 months ago

Is it a Windows environment?

Poor performance on Windows is a known issue. See #213. I am planning a fix in the next milestone.

yuuki0xff commented 10 months ago

nvpy freezes for up to 30s with the rest of the ui being unusable until the search is complete.

30 seconds!? On my Windows environment, I can use nvPY with 1500+ active notes. The response is slow but doesn't freeze for 30 seconds.

Could you take a performance profile by following the steps below?

  1. Append use_profiler = true to nvpy.cfg.
  2. Start nvPY.
  3. Perform the search operation several times.
  4. Exit nvPY. nvPY will generate nvpy-profile-*.txt file under the nvpy data directory (Usually %HOMEDRIVE%%HOMEPATH%/.nvpy/).
  5. Send the first 50 lines of nvpy-profile-*.txt to this issue.
  6. Delete use_profiler = true from nvpy.cfg.
wrathofthomas commented 10 months ago

Thanks for responding! It's not a windows environment. Yes, it can be anywhere from 13-30 seconds per character 1 and <15 for character 2. Deleting characters under the 3 character range takes even more time for some reason.

Here's the log:

         583151 function calls (571165 primitive calls) in 51.074 seconds

   Ordered by: internal time, cumulative time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
38903/38534   43.534    0.001   43.560    0.001 {method 'call' of '_tkinter.tkapp' objects}
        1    4.560    4.560   48.822   48.822 {method 'mainloop' of '_tkinter.tkapp' objects}
        1    0.893    0.893    0.893    0.893 {built-in method _tkinter.create}
     3672    0.307    0.000   36.024    0.010 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:515(append)
       10    0.087    0.009   43.694    4.369 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:2099(set_notes)
     1789    0.087    0.000    0.087    0.000 /usr/lib/python3.11/json/decoder.py:343(raw_decode)
     3672    0.078    0.000    0.078    0.000 {method 'strftime' of 'datetime.date' objects}
     7562    0.071    0.000    0.102    0.000 /usr/lib/python3.11/tkinter/__init__.py:1524(_options)
     7461    0.070    0.000    0.570    0.000 /usr/lib/python3.11/tkinter/__init__.py:1682(_configure)
    39052    0.067    0.000    0.067    0.000 {method 'format' of 'str' objects}
    15047    0.067    0.000    0.102    0.000 /usr/lib/python3.11/tkinter/__init__.py:102(_cnfmerge)
     3672    0.066    0.000    0.066    0.000 {method 'splitlines' of 'str' objects}
    19557    0.065    0.000   34.185    0.002 /usr/lib/python3.11/tkinter/__init__.py:3893(tag_add)
     3672    0.060    0.000    0.198    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/utils.py:54(human_date)
     1798    0.059    0.000    0.059    0.000 {built-in method io.open}
       10    0.055    0.005    0.114    0.011 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:538(filter_notes_gstyle)
    11193    0.045    0.000    0.571    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/tk.py:56(insert)
     3672    0.040    0.000    0.040    0.000 {built-in method fromtimestamp}
    69798    0.040    0.000    0.040    0.000 {method 'get' of 'dict' objects}
     9628    0.038    0.000    0.038    0.000 {method 'match' of 're.Pattern' objects}
    11193    0.034    0.000    0.526    0.000 /usr/lib/python3.11/tkinter/__init__.py:3806(insert)
        1    0.032    0.032    0.412    0.412 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:300(__init__)
    47798    0.032    0.000    0.032    0.000 {built-in method builtins.isinstance}
     1789    0.030    0.000    0.030    0.000 {method 'read' of '_io.BufferedReader' objects}
 11227/17    0.028    0.000   44.505    2.618 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/tk.py:32(wrapper)
     3672    0.025    0.000    0.059    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/utils.py:26(get_note_title)
        5    0.021    0.004    0.030    0.006 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:822(sync_to_server_threaded)
        5    0.021    0.004    0.038    0.008 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:793(save_threaded)
     7426    0.019    0.000    0.563    0.000 /usr/lib/python3.11/tkinter/__init__.py:1695(configure)
     1797    0.018    0.000    0.018    0.000 {method '__exit__' of '_io._IOBase' objects}
     8945    0.017    0.000    0.017    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:1292(need_save)
     1789    0.017    0.000    0.164    0.000 /usr/lib/python3.11/json/__init__.py:299(loads)
     1789    0.017    0.000    0.118    0.000 /usr/lib/python3.11/json/decoder.py:332(decode)
    14969    0.017    0.000    0.017    0.000 {built-in method _tkinter._flatten}
     6868    0.015    0.000    0.015    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:530(<genexpr>)
     1789    0.015    0.000    0.209    0.000 /usr/lib/python3.11/json/__init__.py:274(load)
    19567    0.015    0.000    0.015    0.000 {method 'start' of 're.Match' objects}
     3683    0.014    0.000    0.284    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:656(disable_text)
     7352    0.014    0.000    0.019    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/utils.py:83(note_pinned)
     3672    0.014    0.000    0.014    0.000 {built-in method now}
     3682    0.014    0.000    0.279    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:659(enable_text)
     1789    0.014    0.000    0.021    0.000 /usr/lib/python3.11/json/__init__.py:244(detect_encoding)
    11016    0.014    0.000    0.041    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:149(<genexpr>)
     3672    0.013    0.000    0.055    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:148(__call__)
     4340    0.012    0.000    0.032    0.000 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/notes_db.py:516(_helper_gstyle_mswordmatch)
yuuki0xff commented 10 months ago

The part of I am giving attention:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
38903/38534   43.534    0.001   43.560    0.001 {method 'call' of '_tkinter.tkapp' objects}
     3672    0.307    0.000   36.024    0.010 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:515(append)
       10    0.087    0.009   43.694    4.369 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:2099(set_notes)
    19557    0.065    0.000   34.185    0.002 /usr/lib/python3.11/tkinter/__init__.py:3893(tag_add)

Tk operation proceeded 39k times, and the tag_add proceeded 20k times in 51 seconds. I suspect that text highlighting causes significant performance down.

@wrathofthomas Are you displaying very long text with nvPY? Do you see a lot of highlights in the notes list when you type a few characters into the search box?

wrathofthomas commented 10 months ago

Re displaying long text, I would say no. My notes aren't any longer probably than most people's Re the highlighting. Yes, nvpy is highlighting the searched character(s) in both the list and the body of the visible note. How can it turn it off to test?

yuuki0xff commented 10 months ago

Thanks for your reply.

How can it turn it off to test?

No option provided to turn off highlighting. It needs to edit the source code.

Just remove for loop that calls tag_add() method in NotesList.append() and View.activate_search_string_highlights().

wrathofthomas commented 10 months ago

In view.py of ~/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy? Remove those three quoted sections?

yuuki0xff commented 10 months ago

Yes, that's right.

wrathofthomas commented 10 months ago

Yep that's it. It's immediately responsive now. How do we keep the highlighting feature, and avoid the delay? Maybe only highlight in body?

yuuki0xff commented 10 months ago

I think that you should keep the highlight process in View.activate_search_string_highlights().

https://github.com/cpbotha/nvpy/blob/7fa6ab6fe8aef2492a9981345e66a5c6f89a7b4a/nvpy/view.py#L1816-L1826

wrathofthomas commented 10 months ago

If i leave lines 1816-1826 in and delete the first to sections. The searching is still immediate with no delays but highlighting is kept in body.

wrathofthomas commented 10 months ago

Nice :)

wrathofthomas commented 10 months ago

So how to fix the highlighting in the list?

yuuki0xff commented 10 months ago

The update process of the Notes List was the cause of nvPY slowdown. Adding highlighting to the Notes List made the performance problem worse.

Plans to fix the root cause are listed in the Ideas to improve performance section of https://github.com/cpbotha/nvpy/issues/213#issuecomment-1345379703.

wrathofthomas commented 10 months ago

ok! thanks!

yuuki0xff commented 10 months ago

tag_add is 159x faster, even using 9 years old desktop CPU (Core i5-4460). It suggests that other factors exist.

Your result: tag_add takes 1748 us/call.

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
38903/38534   43.534    0.001   43.560    0.001 {method 'call' of '_tkinter.tkapp' objects}
     3672    0.307    0.000   36.024    0.010 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:515(append)
       10    0.087    0.009   43.694    4.369 /home/garnet/.local/pipx/venvs/nvpy/lib/python3.11/site-packages/nvpy/view.py:2099(set_notes)
    19557    0.065    0.000   34.185    0.002 /usr/lib/python3.11/tkinter/__init__.py:3893(tag_add)

My result: tag_add takes 11 us/call.

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
216481/184862    3.613    0.000    3.649    0.000 {method 'call' of '_tkinter.tkapp' objects}
    10877    0.319    0.000    1.987    0.000 /home/yuuki/repo/github.com/cpbotha/nvpy/nvpy/view.py:515(append)
        7    0.086    0.012    2.223    0.318 /home/yuuki/repo/github.com/cpbotha/nvpy/nvpy/view.py:2099(set_notes)
   106991    0.065    0.000    1.167    0.000 /usr/lib/python3.11/tkinter/__init__.py:3892(tag_add)
wrathofthomas commented 10 months ago

Could it be the venv?

yuuki0xff commented 10 months ago

Yes. nvPY runs inside a venv managed by pipx.

Note that the nvpy module installed with editable mode because I'm developer.

wrathofthomas commented 10 months ago

Would you like me to try to install and run this outside the venv and send you another log?

wrathofthomas commented 10 months ago

I cannot figure out how to do this. If you have any guidance let me know. Thanks!

yuuki0xff commented 10 months ago

Are the Python loads the Tkinter module from the system global area? The Tkinter module is part of the Python Standard Library. So, it should not be affected by venv/pipx. You can check it with the command below:

$ ( . ~/.local/pipx/venvs/nvpy/bin/activate && python3 )
Python 3.11.6 (main, Oct  8 2023, 05:06:43) [GCC 13.2.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import tkinter, _tkinter
>>> tkinter
<module 'tkinter' from '/usr/lib/python3.11/tkinter/__init__.py'>
>>> _tkinter
<module '_tkinter' from '/usr/lib/python3.11/lib-dynload/_tkinter.cpython-311-x86_64-linux-gnu.so'>
wrathofthomas commented 10 months ago

This is what I got.

>>> tkinter
<module 'tkinter' from '/usr/lib/python3.11/tkinter/__init__.py'>
>>> _tkinter
<module '_tkinter' from '/usr/lib/python3.11/lib-dynload/_tkinter.cpython-311-x86_64-linux-gnu.so'>

Looks the same as yours

yuuki0xff commented 10 months ago

The location that makes tag_add() slow is the UI library (_tkinter, libtk, and libtcl), or further lower layers. We will need to narrow down the suspect area with perf.

A quick check in my debian environment gave me harsh results. The reason is that libtk does not have debugging symbols and most lines were displayed with hexadecimal addresses. You may need to build libtk and libtcl with the -g compile option.

wrathofthomas commented 10 months ago

I am not sure how to build libtk and libtcl with the -g compile option, but happy to do it if you give me some instructions!

yuuki0xff commented 10 months ago

See https://github.com/cpbotha/nvpy/blob/master/docs/ucs-4.rst. This documentation was written 3 years ago for other purpose, but it will still be helpful.

The documentation describes build procedure for older version. You are better off building the latest version. The procedure will be almost the same.

Build artifacts will be placed on /opt/nvpy/. The LD_LIBRARY_PATH environment variable is probably required to start the self-built python.

wrathofthomas commented 10 months ago

Will give this a try and let you know if I am successful