search

andreikop / enki

A text editor for programmers
http://enki-editor.org
GNU General Public License v2.0
161 stars 38 forks source link

Slow startup #83

Closed andreikop closed 11 years ago

andreikop commented 11 years ago

vi:

  1. "hot" startup time. Old enki: about 3 seconds, master enki: about 7 seconds; Maybe they can be combined? Enki starts in "lightweight editor" mode (without syntax highlight at all), then goes to qutepart mode...
andreikop commented 11 years ago

What is your PC hardware?

Could you please

  1. Open C file (it will be reopened during next startup session restore)
  2. Close Enki
  3. Do few times enki -p and paste the console output

Do this steps for 12.08.5 and current master.

vi commented 11 years ago

Hardware is Asum EeePC 1015PEM. Filesystem (reiserfs) is currently slowed down by multiple LVM snapshots + encryption, hovewer I was testing when both Enkies were in cache and starting them wasn't causing significant HDD activity. There were already several C files opened.

Old enki:

Import PyQt4                  : 7
Import QScintilla             : 235
Import modules                : 0
Construct application         : 71
Catch SIGINT                  : 85
create main window            : 124
create config                 : 7
Create UISettings             : 14
import workspace              : 65
create workspace              : 21
Create FileFilter             : 6
Create Locator                : 42
Search plugins                : 176
  Load appshortcuts           : 9
  Load associations           : 8
  Load cppfileswitch          : 6
  Load detectindent           : 4
  Load editor                 : 102
  Load editortoolbar          : 18
  Load filebrowser            : 34
  Load helpmenu               : 10
  Load mitscheme              : 10
  Load preview                : 12
  Load recentfiles            : 7
  Load restorepos             : 8
  Load schemeindenthelper     : 8
  Load searchreplace          : 35
  Load session                : 4
  Load workspace_actions      : 8
  Load workspace_commands     : 26
Open files                    : 0
Restore session               : 705
Load state                    : 38
Show main window              : 0
Total                         : 1905

Qutepart enki:

Import PyQt4                  : 6
Import modules                : 171
Construct application         : 57
Catch SIGINT                  : 6
create main window            : 72
create config                 : 2
Create UISettings             : 2
import workspace              : 6
create workspace              : 23
Create FileFilter             : 4
Create Locator                : 16
Search plugins                : 127
  Load appshortcuts           : 3
  Load cppfileswitch          : 1
  Load detectindent           : 0
  Load editortoolbar          : 6
  Load filebrowser            : 7
  Load helpmenu               : 4
  Load preview                : 1
  Load qpartsettings          : 1
  Load recentfiles            : 2
  Load repl                   : 2
  Load restorepos             : 4
  Load searchreplace          : 9
  Load session                : 0
  Load workspace_actions      : 1
  Load workspace_commands     : 3
Open files                    : 0
Restore session               : 391
Load state                    : 91
Show main window              : 0
Total                         : 1018

Variance is not too big to consider.

Also obtained strace dumps for both Enkis:

strace -Ttttf -o enkiold.strace enki -p  # /usr/local/bin/enki
strace -Ttttf -o enkiqutep.strace enkiq -p # PYTHONPATH=/home/vi/src/git/enki exec /home/vi/src/git/enki/bin/enki "$@"

http://vi-server.org/pub/enki_strace.7z

andreikop commented 11 years ago

I see 1 second startup time here. Quite good for slow (compared with average PC, used for coding novadays) machine. 200 ms on mine PC

There are no any random processes in Enki. If startup time sometimes is bigger - it means your system is loaded with other processes

vi commented 11 years ago

1 second is good. By my startup is about 7 seconds:

$ time enkiq -p
...
Total                         : 1504

real    0m7.979s
user    0m6.640s
sys 0m0.270s

Note: there are 13 C files in session that gets opened when I start Enki.

andreikop commented 11 years ago

I fixed bug in the profiler. Previous version counted only times < 1 second. Was always enough for me. Could you please pull master and send enki -p output once more?

vi commented 11 years ago 
~/src/git/enki$ time python -c 'import sys, os.path, traceback, logging, logging.handlers, optparse, enki.core.defines, datetime; import enki; print "wtf"'
wtf

real    0m0.174s
user    0m0.150s
sys 0m0.020s
$ time enkiq -p
Import PyQt4                  : 7
Import modules                : 244
Construct application         : 67
Catch SIGINT                  : 9
create main window            : 98
create config                 : 2
Create UISettings             : 2
import workspace              : 6
create workspace              : 20
Create FileFilter             : 4
Create Locator                : 11
Search plugins                : 98
  Load appshortcuts           : 4
  Load cppfileswitch          : 1
  Load detectindent           : 1
  Load editortoolbar          : 8
  Load filebrowser            : 9
  Load helpmenu               : 5
  Load preview                : 2
  Load qpartsettings          : 2
  Load recentfiles            : 2
  Load repl                   : 3
  Load restorepos             : 6
  Load searchreplace          : 13
  Load session                : 1
  Load workspace_actions      : 2
  Load workspace_commands     : 5
Open files                    : 0
Restore session               : 384
Load state                    : 95
Show main window              : 0
Total                         : 1111

real    0m1.453s
user    0m1.320s
sys 0m0.100s

Strange. Now Qutepart enki starts even faster than old Enki, even if I revert it to e1cc36b84463e02e8f7593e26041fe699c2534c4...

vi commented 11 years ago

Oh, it was actually only one cpp file in the session.

Re-checked dfb7e8d10d7d2865c047e96ba784de08e3942358 with 20 .c and .h files in session:

~/src/git/enki$ time bin/enki -p
Import PyQt4                  : 11
Import modules                : 284
Construct application         : 78
Catch SIGINT                  : 10
create main window            : 108
create config                 : 2
Create UISettings             : 2
import workspace              : 6
create workspace              : 21
Create FileFilter             : 4
Create Locator                : 11
Search plugins                : 99
  Load appshortcuts           : 4
  Load cppfileswitch          : 1
  Load detectindent           : 1
  Load editortoolbar          : 8
  Load filebrowser            : 10
  Load helpmenu               : 5
  Load preview                : 2
  Load qpartsettings          : 2
  Load recentfiles            : 2
  Load repl                   : 3
  Load restorepos             : 6
  Load searchreplace          : 13
  Load session                : 1
  Load workspace_actions      : 2
  Load workspace_commands     : 5
Open files                    : 0
Restore session               : 670
Load state                    : 81
Show main window              : 0
Total                         : 1452

real    0m10.994s
user    0m10.570s
sys 0m0.280s
vi commented 11 years ago

Why "Open files" is always "0"? The most slowdown when checking with strace -fe open bin/enki -p I see when it openes the last session source files:

[pid 28303] open("/mnt/src/git/cjdns/dht/dhtcore/NodeCollector.h", O_RDONLY|O_LARGEFILE) = 21
[pid 28322] open("/proc/stat", O_RDONLY|O_CLOEXEC) = 21
Process 28323 attached
[pid 28303] open("/mnt/src/git/cjdns/dht/dhtcore/NodeHeader.h", O_RDONLY|O_LARGEFILE) = 23
[pid 28323] open("/proc/stat", O_RDONLY|O_CLOEXEC) = 23
Process 28324 attached
[pid 28303] open("/mnt/src/git/cjdns/dht/dhtcore/NodeList.h", O_RDONLY|O_LARGEFILE) = 25
[pid 28303] open("/proc/stat", O_RDONLY|O_CLOEXEC) = 25
Process 28325 attached
[pid 28325] open("/proc/stat", O_RDONLY|O_CLOEXEC) = 26
[pid 28303] open("/mnt/src/git/cjdns/dht/dhtcore/NodeStore.c", O_RDONLY|O_LARGEFILE) = 27
andreikop commented 11 years ago

Oops, there are bug in time calculation again. I pushed one more fix.

Open files means opening files, passed as command line arguments.

Real time consumer is 'Restore session' for big count of files. Now it is visible in the enki -p output. I'll try to fix it.

vi commented 11 years ago 
$ time enkiq -p
Import PyQt4                  : 8
Import modules                : 264
Construct application         : 1347
Catch SIGINT                  : 143
create main window            : 469
create config                 : 96
Create UISettings             : 19
import workspace              : 32
create workspace              : 153
Create FileFilter             : 42
Create Locator                : 85
Search plugins                : 123
  Load appshortcuts           : 9
  Load cppfileswitch          : 35
  Load detectindent           : 2
  Load editortoolbar          : 36
  Load filebrowser            : 71
  Load helpmenu               : 33
  Load preview                : 22
  Load qpartsettings          : 23
  Load recentfiles            : 33
  Load repl                   : 33
  Load restorepos             : 47
  Load searchreplace          : 33
  Load session                : 1
  Load workspace_actions      : 4
  Load workspace_commands     : 54
Open files                    : 0
Restore session               : 11386
Load state                    : 108
Show main window              : 0
Total                         : 14711

real    0m15.480s
user    0m11.380s
sys 0m0.450s
andreikop commented 11 years ago

I've improved startup time. Please pull qutepart master, install qutepart, and check.

Code is complicated and fresh, might be buggy. Just check out previous revision, if having problems.

vi commented 11 years ago

Checking with 209 C files:

Old enki: 16.297s + virtual memory about 1100M qutepart 695dede02a67cf0dcb1e1c0e3c184371efee2423: 1m21.552s + virtual memory about 1100M qutepart 37b191280ac93d78307028b3c400487cca179006: 0m57.142s + virtual memory about 1100M

Unsatisfactory...

Also why does Enki use so many threads (129 in this test, both old and qutepart)? The main slowdown is when it alternates file opens with thread starts while restoring the session.

andreikop commented 11 years ago

Hmm, looks strange. Difference between 695dede and 37b1912 should be bigger. 695dede startup time should be bigger.

What is your system configuration? Do you install qutepart to the system, or use from src tree? (If executed from the source tree, slow parser in python is used instead of quick parser in C) Are you sure you installed qutepart before running tests, and test results are correct?

On Fri, Jun 14, 2013 at 2:37 PM, Vitaly Shukela notifications@github.comwrote:

Checking with 209 C files:

Old enki: 16.297s + virtual memory about 1100M qutepart 695dedehttps://github.com/hlamer/enki/commit/695dede02a67cf0dcb1e1c0e3c184371efee2423: 1m21.552s + virtual memory about 1100M qutepart 37b1912https://github.com/hlamer/enki/commit/37b191280ac93d78307028b3c400487cca179006: 0m57.142s + virtual memory about 1100M

Unsatisfactory...

Also why does Enki use so many threads (129 in this test, both old and qutepart)? The main slowdown is when it alternates file opens with thread starts while restoring the session.

— Reply to this email directly or view it on GitHubhttps://github.com/hlamer/enki/issues/83#issuecomment-19452281 .

vi commented 11 years ago

I uninstalled local-qutepart_0.440.695dede-1_i386.deb, then created and installed local-qutepart_0.443.37b191280-1_i386.deb; that delibers qutepart into /usr/local/lib/python2.7/dist-packages/qutepart/.

Maybe create some test in qutepart itself (not using enki -p)?

andreikop commented 11 years ago

OK, it seems your tests are correct. I'll try to open 209 files and see, how quick they are opened for me

On Fri, Jun 14, 2013 at 3:24 PM, Vitaly Shukela notifications@github.comwrote:

I uninstalled local-qutepart_0.440.695dede-1_i386.deb, then created and installed local-qutepart_0.443.37b191280-1_i386.deb; that delibers qutepart into /usr/local/lib/python2.7/dist-packages/qutepart/.

Maybe create some test in qutepart itself (not using enki -p)?

— Reply to this email directly or view it on GitHubhttps://github.com/hlamer/enki/issues/83#issuecomment-19454053 .

andreikop commented 11 years ago

Could you update qutepart and Enki and check current version?

vi commented 11 years ago

Now old enki works (on the same set of 209 C files) in 0m21.772s.

Enki a110207300a5b320eed2d8cf336b1794ac7ba215 + qutepart 00379b3d0e67d8fbc9dd5cf7d1fa1c71d9a5d2c9: 0m27.943s

Import PyQt4                  : 8
Import modules                : 583
Construct application         : 72
Catch SIGINT                  : 10
create main window            : 114
create config                 : 2
Create UISettings             : 3
import workspace              : 5
create workspace              : 20
Create FileFilter             : 4
Create Locator                : 16
Search plugins                : 93
  Load appshortcuts           : 4
  Load cppfileswitch          : 1
  Load detectindent           : 1
  Load editortoolbar          : 8
  Load filebrowser            : 11
  Load helpmenu               : 5
  Load preview                : 2
  Load qpartsettings          : 2
  Load recentfiles            : 2
  Load repl                   : 3
  Load restorepos             : 5
  Load searchreplace          : 14
  Load session                : 1
  Load workspace_actions      : 2
  Load workspace_commands     : 5
Open files                    : 0
Restore session               : 23579
Load state                    : 70
Show main window              : 0
Total                         : 24645

Now it's reasonable.

After opening those files, I see syntax highlight getting enabled from last to first file, sequentially. Do we really need to calculate background syntax highlight for unvisited files? Should we prioritize currently active file for highlighting?

I sometimes open Enki by "enki .c .h", so there can be sessions with many files, and not all of them are actually needed to be displayed.

andreikop commented 11 years ago

OK. There might be room for further optimization, but I don't won't to make code more complicated, unless somebody asks about it.

About highlighting visible file first - open issue, if you think it is critical. It is possible to do, but I'm not sure if I should invest time for this task and make the code more complicated.

vi commented 11 years ago

OK. If I get annoyed by this in real work (as opposed to synthetic test), I'll open an issue.