Start up lag - Githubissues

blitzmann commented 6 years ago

I'm not sure if this is still an issue, but there have been a few reports in the 2.x series of pyfa taking a long time to start up. I'm creating this issue to link the other issues.

If you're experiencing this issue

First, please subscribe to the thread to receive new updates and posts! The subscribe button it to the right.

Attaching log files can help determine where the slow down is taking place. Your logs are found in %userprofile%/.pyfa and end in .log. Find the one that shows longish start up times (each log is time-stamped so it should be easy-ish to find gaps when it starts...). it may be helpful to dump the current log to disk by going to Preferences > Logging > Dump all logs

As I investigate, I may also post in this thread new builds that have additional logging to try to narrow down where the issues lie. it would be helpful to keep an eye on notification for any updates to this thread and provide logs and feedback as I work through this progress.

Thanks!

Calavoow commented 6 years ago

My pyfa has been starting noticeably slower since 2.0. Here are my logs pyfa-2018-05-31.log

blitzmann commented 6 years ago

Thanks @Calavoow! That log shows about 3 seconds of start up, which isn't too bad and kind of normal. Dump another log if you notice it taking much longer than that :) (unless of course this one as a long startup, and the log just didn't catch it?)

Calavoow commented 6 years ago

Another one, after a fresh start pyfa-2018-06-01.log Seems like 13 seconds this time

blitzmann commented 6 years ago

Thanks!

I need to put a lot more debugging statements when various thing initialize to try to track down where this is taking a while. I'll try to get you a test build that you can run that should show a lot more granularity

Nimos commented 6 years ago

pyfa_debug-2018-06-01.log

here's one of mine, I've been struggling with long startup times for a while

blitzmann commented 6 years ago

I'm attempting something that is either completely clever, or completely crazy

With bb978c3dffd772d48304af123a33d4827184da06 you should now be able to specify a path to save profiling information. While this introduces additional overhead, as well as possible increased start up times, it will track the function calls within pyfa and allow me to determine what is eating up time. This will save to file in whatever directory you specify, and then you can upload it here for me to analyse.

If you don't specify a profile location, then it works just as it does now, so no overhead

I'll try to get a build out tonight and distribute in this thread for you guys to try this. I'm interested in seeing if it works out. :)

blitzmann commented 6 years ago

greetings all!

If you wouldn't mind, please download this build: https://ufile.io/dpw4a

You should be able to run this with the -p flag: open up command prompt, and run the pyfa.exe like so:

pyfa.exe -p c:\my\path\to\save\profiles

When you do this, pyfa will automatically save a profiled instance to the path you specify, in a file called pyfa-<data>.profile.

What I want you guys to do: start pyfa with that command, and when it loads, immediately close it. I don't want you to do a full on fitting session as that would probably be too much data to parse through. Just open it, wait for it to load, and then close it (or, if you want, go and dump the log as well). If you're able to get a lengthy start up, please upload the .profile file here and I can take a look at it.

Thanks!

fsufitch commented 6 years ago

+1 on this. The development build of 2.x was starting slowly, but I figured that was before it went through the optimizations prior to being published. I was only half right. The published version is faster than the dev version, but still slower than 1.x Pyfa by a wide margin.

@blitzmann your ufile.io download is not working. Neither of the download buttons do anything.

blitzmann commented 6 years ago

your ufile.io download is not working. Neither of the download buttons do anything.

Works for me...

Here's an alternative: https://drive.google.com/file/d/14jrMCMd0wiN37VSobckJVM64Fz7CuIOL/view?usp=sharing

Download icon on top right corner

fsufitch commented 6 years ago

pyfa-20180604_180258.zip

blitzmann commented 6 years ago

Thanks! Will take a look. Can you also post the log file? What kind of delay were you getting?

fsufitch commented 6 years ago

I was getting 4-5 second startup time on my work laptop, which is i7 8650U with a fast NVMe SSD. It's slower (7-10 sec) on my gaming desktop at home. I can't get the log now, but will do so later.

Leandrid commented 6 years ago

I'm getting huge startup lag as well, it usually takes a couple of minutes for pyfa to start. Log attached. pyfa-2018-06-18.log

blitzmann commented 6 years ago

@Leandrid can you try https://github.com/pyfa-org/Pyfa/issues/1605#issuecomment-394109462 (file mirror here https://github.com/pyfa-org/Pyfa/issues/1605#issuecomment-394488250) and post the profile? That is a huge startup time, and unfortunately the log only shows this

[2018-06-18 08:32:52.016219] DEBUG: service.fit: Initialize Fit class
[2018-06-18 08:34:19.191647] DEBUG: gui.statsPane: Setting full view for: resources

Which doesn't really help (a lot of things happen in between Fit class and the stat init... :/)

EDIT: Doesn't really help in narrowing it down, but it's more data! Seems the other logs that I have also have a bit of a delay between these two logs as well, so probably something is going on. :)

Leandrid commented 6 years ago

Here you go, log and profile file. pyfa-2018-06-18.log

pyfa-20180618_164107.zip

blitzmann commented 6 years ago

Thank you! Will definitely take a look at this :)

Leandrid commented 6 years ago

Hope it helps :-)

taltracyn commented 6 years ago

2.3.1 is missing all the boosters like standard exile and blue pill from the implants & boosters section.

stackflows commented 5 years ago

I am not sure what "slow" is, but pyfa takes way longer to start then huge bludgers like Word or Excel, at least thrice as long at its best.

blitzmann commented 5 years ago

This issue kind of fell by the wayside unfortunately, but I'm going to make another push at figuring it out.

@Leandrid your profile showed something interesting:

__generateHandler is a function pyfa that looks up effect files and imports them. But that function itself isn't causing the issue, it's the low-level implementation of the import module.

I am unsure if this is due to

The change to importing from python 3
The change to using pyInstaller

But it seems that importing these files is pretty darn expensive.

Tell me, is it slow only on startup, or when opening fits as well? Do you have "load previous fits" enabled in preferences (and if so, does turning it of improve the speed of start up?)

Can everyone in here that is experiencing startup lag do that same thing as described before:

pyfa.exe -p c:\my\path\to\save\profiles

What I want you guys to do: start pyfa with that command, and when it loads, immediately close it. I don't want you to do a full on fitting session as that would probably be too much data to parse through. Just open it, wait for it to load, and then close it (or, if you want, go and dump the log as well). If you're able to get a lengthy start up, please upload the .profile file here and I can take a look at it.

pyfa builds now come with -p so there's no reason to download a special build to obtain this functionality. Post the profile files here and I can take a look at them. I want to find comonality between everyone - I'm looking for if everyone's troubles seem to stem from the importer, or if cetain folks have another hiccup.

Thanks!

blitzmann commented 5 years ago

can everyone experiencing this issue try this build:

https://ci.appveyor.com/project/blitzmann/pyfa/builds/23129072/artifacts

it's using a new method for running effects - instead of importing effect files, all effects are compiled into one large module that gets imported. I'm hoping this decreases issues with io.open.

blitzmann commented 5 years ago

Does the latest release help with the startup issues everyone?

Calavoow commented 5 years ago

I try to execute with the latest stable release (v2.8)

.\pyfa.exe -p ~\profiles

where ~\profiles is an existing directory. On closing pyfa I get an error message: "Fatal Error! Failed to execute script pyfa" and no profile is created.

blitzmann commented 5 years ago

@Calavoow I've noticed this happening sometimes as well. It seem to happen off / on. Try gain a few more times and see if it works. Honestly, this is such a niche flag that I'm not interested in tackling why it only sometimes works :)

ghost commented 5 years ago

I'm having this issue too, it takes a couple of minutes or so to start up, each time. Log:

pyfa-2019-05-21.log

DarkFenX commented 5 years ago

@MisfitMarius do you have some kind of AV monitor installed? Is it an issue which appeared in one of recent releases of pyfa?

ghost commented 5 years ago

@DarkFenX by "AV monitor" I assume you mean anti-virus software? If so, then yes, I use Kaspersky Internet Security, plus whatever Windows 10 features that aren't deactivated by installing KIS, if any. In KIS, pyfa.exe is listed as a Trusted application. As for recent pyfa releases, then yes, the issue has only just started happening. For some context, I'm not actually playing EVE atm, and haven't been for some months now, but the EVE client, and associated tools - including pyfa - remain installed on my machine, in anticipation of my inevitable return. I just fire up the EVE client, EVEMon, pyfa, etc, once in a while to stay updated. This issue with pyfa has only started within the last few weeks. I'm sorry that I cannot be more specific than that. In addition, I have noticed something (that I consider to be) odd. When I launch pyfa, if I ctrl+alt+delete into Task Manager, on the Processes tab pyfa.exe appears under the Background Processes section. But, when pyfa has finished loading, it moves to the Apps section of the Task Manager Processes tab and is fully functional. As far as I can see, anyway. Let me know if I can help further

DarkFenX commented 5 years ago

@MisfitMarius yes, i mean anti-virus monitor.

it could be a regression introduced by 2.9.0 (fix for #1828, although load time increase on my laptop is only 12ms). Please try downloading 2.8.0 and see if it's better (rename <user folder>\.pyfa temporarily if it fails to start). If it is, download 2.9.0 and see if it has the regression. If it does not, try the latest build and see if you still have the issue with clean database (before moving your old data back).

Alternatively - if you know what git bisect is, how to use it and you're able to run pyfa from source - could use it instead.

Regarding background processes - I do not know what the classification is. Will look it up later.

ghost commented 5 years ago

@DarkFenX And, just like that, the issue has stopped occurring. I have absolutely no idea why. If it starts happening again, I'll be sure to report back. Thanks anyway o7

EricE commented 5 years ago

My turn. I had a slow startup version previously but ignored it until it went away with a later version. I just installed the latest version (pyfa-v2.9.6-win.exe) and it is slow again. I watched in the task manager and pyfa slowly counts up to about 120MB and then it displays. I see some errors in the log file but don't know what they mean. I used a timer on my phone and it takes almost 90s to startup. pyfa-2019-08-02.log

DarkFenX commented 5 years ago

Errors are irrelevant, however exact timings can tell a thing or two.

This part could be better:

[2019-08-02 04:38:17.098203] INFO: __main__: Running in a frozen state.
[2019-08-02 04:38:21.629139] INFO: eos.db: Initializing database
[2019-08-02 04:38:21.629139] INFO: eos.db: Gamedata connection: sqlite:///D:\Program Files (x86)\pyfa\eve.db?check_same_thread=False
[2019-08-02 04:38:21.629139] INFO: eos.db: Saveddata connection: sqlite:///C:\Users\Eric\.pyfa\saveddata.db?check_same_thread=False
[2019-08-02 04:38:27.280319] DEBUG: service.prefetch: Run database migration.

But this is just awful:

[2019-08-02 04:38:27.358320] DEBUG: service.prefetch: Completed database validation.
[2019-08-02 04:38:31.180452] INFO: gui.bitmap_loader: Using local image files.
[2019-08-02 04:38:45.569105] DEBUG: service.market: Initialize ShipBrowserWorkerThread.
[2019-08-02 04:38:45.626109] DEBUG: service.fit: Initialize Fit class
[2019-08-02 04:39:13.427166] DEBUG: gui.statsPane: Setting full view for: resources

DarkFenX commented 5 years ago

For the reference, startup times from my machine:

[2019-08-07 05:33:56.289815] INFO: __main__: Running in a thawed state.
[2019-08-07 05:33:56.321459] INFO: eos.db: Initializing database
[2019-08-07 05:33:56.321507] INFO: eos.db: Gamedata connection: sqlite:////home/dfx/Workspace/eve/pyfa/eve.db?check_same_thread=False
[2019-08-07 05:33:56.321535] INFO: eos.db: Saveddata connection: sqlite:////home/dfx/.pyfa/saveddata.db?check_same_thread=False
[2019-08-07 05:33:56.399150] DEBUG: service.prefetch: Run database migration.
...
[2019-08-07 05:33:56.466767] DEBUG: service.prefetch: Completed database validation.
[2019-08-07 05:33:56.581923] INFO: gui.bitmap_loader: Using local image files.
[2019-08-07 05:33:56.658212] DEBUG: service.market: Initialize ShipBrowserWorkerThread.
[2019-08-07 05:33:56.696889] DEBUG: service.fit: Initialize Fit class
[2019-08-07 05:33:57.099069] DEBUG: gui.statsPane: Setting full view for: resources

It takes under 1 second to get to the last line while in your log it takes pyfa almost a minute.

@EricE which antivirus/scanning/monitoring software are you using?

ghost commented 5 years ago

Having just updated from 2.9.4 to 2.9.6, this issue has returned. All the info I presented in my comments from 21st May, the first time it happened, still applies. Log:

pyfa-2019-08-08.log

Funnily enough, when I started 2.9.4, the issue didn't occur - the "update available" window appeared upon pyfa loading, and from there I navigated to github downloads, downloaded the 2.9.6 .zip, and copied the contents across and over my existing pyfa folder. From there I restarted pyfa, and the issue has occurred since

EricE commented 5 years ago

Hmm, just started up 2.9.6 and it started very quickly... I tried twice and it was great both times. I'm using Kaspersky Internet Security 19. No changes to my system that I can think of between the two reports.

pyfa-2019-08-09.log

DarkFenX commented 5 years ago

My guess is that as AV monitor is collecting data about executable into global databases, it is monitoring pyfa in "strict" mode which slows down certain operations.

I will try to add more logging between lines I posted above to see what exactly is causing it.

DarkFenX commented 5 years ago

I've added some extra logging in 9803da18258598e286256b71f78d61a215e029a5. No idea if it will be enough, but atm I do not feel like I am ready to log every function call.

ghost commented 5 years ago

@DarkFenX I've posted a question in 9803da1. Thanks

DarkFenX commented 5 years ago

@MisfitMarius https://ci.appveyor.com/project/blitzmann/pyfa/builds/26758783/artifacts Download one of those builds, launch and see if it still launches so long. If it is, provide log file.

(I have not tested if these builds work yet btw, this is still work in progress so they might be broken)

ghost commented 5 years ago

@DarkFenX Gah, my tardiness has overlapped this process with 2.10's release. Sorry about that. That said, I downloaded the .zip from the link you gave, and it started quickly. Here's the log, for what it's worth:

pyfa-2019-08-23.log

I'll go and try 2.10 now, I'll report back soon

ghost commented 5 years ago

And 2.10 is fine, thanks! I'll see how things go and report back if necessary

DarkFenX commented 5 years ago

that's funny because I did not change anything for startup lag. Thanks for logs, i will check them later

pyfa-org / Pyfa

Start up lag #1605

If you're experiencing this issue