Poor performance in SchematicCleanUp() in eeschema

[Chris Pavlina]

I'm not sure which recent change caused this (could be the library system or several other candidates), but KiCad now freezes for at least 20 seconds when switching sheets in one of my larger projects.

Application: kicad
Version: (2017-12-09 revision 48388695a)-master, debug build
Libraries:
    wxWidgets 3.0.3
    libcurl/7.57.0 OpenSSL/1.1.0g zlib/1.2.11 libidn2/2.0.4 libpsl/0.18.0 (+libidn2/2.0.4) libssh2/1.8.0 nghttp2/1.28.0
Platform: Linux 4.14.4-1-ARCH x86_64, 64 bit, Little endian, wxGTK
Build Info:
    wxWidgets: 3.0.3 (wchar_t,wx containers,compatible with 2.8) GTK+ 2.24
    Boost: 1.65.1
    Curl: 7.57.0
    Compiler: GCC 7.2.0 with C++ ABI 1011

Build settings:
    USE_WX_GRAPHICS_CONTEXT=OFF
    USE_WX_OVERLAY=OFF
    KICAD_SCRIPTING=ON
    KICAD_SCRIPTING_MODULES=ON
    KICAD_SCRIPTING_WXPYTHON=ON
    KICAD_SCRIPTING_ACTION_MENU=OFF
    BUILD_GITHUB_PLUGIN=ON
    KICAD_USE_OCE=ON
    KICAD_SPICE=ON

[Wayne Stambaugh (stambaughw)]

Is this only on the first sheet switch or every sheet switch? Please
keep in mind, the new symbol library table uses lazy loading so if you
open a sheet with symbols in libraries that have not been opened yet,
there will be a performance penalty as the libraries are parsed.
However, 20 seconds seems way out of line from what I have seen (<1s).
I could move this time penalty to the start up time of Eeschema and just
load every library at launch time and then it should not be issue. Try
opening symbol chooser first because it load every symbol in the symbol
library table and see if that improves your sheet load performance.
Technically the new symbol loading should be faster because there is no
more searching every library for a symbol name unit it's found unless
the symbol cannot be found in it's specified library and falls back to
the cache library.

On 12/09/2017 05:58 PM, Chris Pavlina wrote:
> Public bug reported:
>
> I'm not sure which recent change caused this (could be the library
> system or several other candidates), but KiCad now freezes for at least
> 20 seconds when switching sheets in one of my larger projects.
>
> Application: kicad
> Version: (2017-12-09 revision 48388695a)-master, debug build
> Libraries:
> wxWidgets 3.0.3
> libcurl/7.57.0 OpenSSL/1.1.0g zlib/1.2.11 libidn2/2.0.4 libpsl/0.18.0 (+libidn2/2.0.4) libssh2/1.8.0 nghttp2/1.28.0
> Platform: Linux 4.14.4-1-ARCH x86_64, 64 bit, Little endian, wxGTK
> Build Info:
> wxWidgets: 3.0.3 (wchar_t,wx containers,compatible with 2.8) GTK+ 2.24
> Boost: 1.65.1
> Curl: 7.57.0
> Compiler: GCC 7.2.0 with C++ ABI 1011
>
> Build settings:
> USE_WX_GRAPHICS_CONTEXT=OFF
> USE_WX_OVERLAY=OFF
> KICAD_SCRIPTING=ON
> KICAD_SCRIPTING_MODULES=ON
> KICAD_SCRIPTING_WXPYTHON=ON
> KICAD_SCRIPTING_ACTION_MENU=OFF
> BUILD_GITHUB_PLUGIN=ON
> KICAD_USE_OCE=ON
> KICAD_SPICE=ON
>
> ** Affects: kicad
> Importance: Low
> Status: New
>
>
> ** Tags: eeschema
>

[Chris Pavlina (pavlina-chris)]

This is every switch. If you want to check out the project:

git clone --recursive https://github.com/c4puter/motherboard

That will pull down the entire project including the libraries it uses. This is my favorite project for complaining about KiCad because it's impossibly slow _everywhere_ ;) but this one is new...

[Chris Pavlina (pavlina-chris)]

Looks like it depends on the complexity of the individual sheet being switched to. The "CPU" sheets are horrifically slow; Root, Misc and so on are pretty quick.

[Seth Hillbrand (sethh)]

Hi Chris-

Try this patch and see if it helps your loading. I checked with your example board on my linux machine and see about 1s loading for each sheet.

-S

[Chris Pavlina (pavlina-chris)]

Looks good! I don't have time to review it tonight but I'll say that it helps.

Still... it takes like 20s to load each sheet the first time. Your patch fixes subsequent loads, but 20s _per sheet_ the first time in a big project still seems unreasonable to me, especially when it was much shorter before and when kicad totally freezes for that time...

[Chris Pavlina (pavlina-chris)]

Okay, I have to update, because I misunderstood Wayne above and responded inaccurately.

Wayne, this does not happen on every sheet switch, but it happens on the first switch to _each sheet_. I maintain that that is still unacceptable. In this project I could spend over a full minute just loading sheets each time I start eeschema, and at this phase of the project I'm frequently popping it up for reference and then closing it. Really not good.

Seth, I'm sorry to report that your patch doesn't actually speed anything up for me now that I've realized what's going on.

[jean-pierre charras (jp-charras)]

Hi Chris,
I downloaded the "motherboard" project and its libraries, and I have no delay when opening project subsheets.
(W7 32bits)

[Chris Pavlina (pavlina-chris)]

Interesting, I can't imagine why it'd be OS dependent, or otherwise work differently for you.

Also slightly confusingly, I just noticed that the delay happens _after_ the sheet is loaded - that is, it fully renders, then KiCad freezes for 20 seconds.

[jean-pierre charras (jp-charras)]

This is also the case for me, but the delay is 1 to 2 seconds in the worst case.
(slightly slower if the project is stored on a hard disk, slightly faster if stored on a SSD)

[Seth Hillbrand (sethh)]

Chris,

On one of your slow sheets, do you also have very slow behavior when you draw a new wire connection between two existing wires?

[jean-pierre charras (jp-charras)]

More info:
In debug build, the delay is 20 seconds or more, and draw a new wire connection between two existing wires is also very long.

[Chris Pavlina (pavlina-chris)]

Seth - yup! It freezes for about the same amount of time.

JP - oh, good catch - I forgot to check whether I was running release or debug. Not sure when my build got switched over as I'd been running pretty exclusively RelWithDebInfo builds for a while...

Okay, it's much less important if it's only on a debug build. I still won't close this report myself as I worry the issue is still there (and might show up on release builds for even _more_ complex boards) but if someone else thinks it's a non-issue I suppose they can.

[Wayne Stambaugh (stambaughw)]

Is is possible someone left some extraneous debugging output statements
in their code that would cause this?

On 12/10/2017 10:59 AM, jean-pierre charras wrote:
> More info:
> In debug build, the delay is 20 seconds or more, and draw a new wire connection between two existing wires is also very long.
>

[Chris Pavlina (pavlina-chris)]

On second thought, I think I would still consider this a bug even in release builds because it applies to wires too --- 1 second per sheet switch is tolerable, but imagine how infuriating it'd be to wire up a complex schematic with kicad freezing on every wire...

[Wayne Stambaugh (stambaughw)]

I suspect the problem is not library loading but rather the new
bus/wire/junction code that could be the issue. If you get some time
please try commenting out the SchematicCleanUp() function call on line
371 of eeschema/files_io.cpp. If this makes the problem go away, then
it is most likely the new bus/wire/junction code. I doubt I will have
time to get to it over the next day or so. I will take a look at it
when I get a chance.

On 12/10/2017 1:34 PM, Chris Pavlina wrote:
> Seth - yup! It freezes for about the same amount of time.
>
> JP - oh, good catch - I forgot to check whether I was running release or
> debug. Not sure when my build got switched over as I'd been running
> pretty exclusively RelWithDebInfo builds for a while...
>
> Okay, it's much less important if it's only on a debug build. I still
> won't close this report myself as I worry the issue is still there (and
> might show up on release builds for even _more_ complex boards) but if
> someone else thinks it's a non-issue I suppose they can.
>

[Chris Pavlina (pavlina-chris)]

Yup, you got it! The performance is quite acceptable with that line commented out.

[Seth Hillbrand (sethh)]

I suspect that it is an optimization of CleanupSchematic() that causes release vs. debug to behave so differently. There's probably some caching of connectivity results that can speed it up and avoid the n^2 behavior.

[Wayne Stambaugh (stambaughw)]

Thanks for testing this. I'm going to remove this since it causes the
board to modified in some cases which is a separate bug report. Of
course this is just kicking the can down the road because any action
that triggers a schematic clean up is going have the delay.

On 12/10/2017 01:53 PM, Chris Pavlina wrote:
> Yup, you got it! The performance is quite acceptable with that line
> commented out.
>
> ** Summary changed:
>
> - Poor performance switching sheets in eeschema
> + Poor performance in SchematicCleanUp() in eeschema
>

[Seth Hillbrand (sethh)]

Chris-

Would you mind testing this patch to see if it resolves your speed issue?

This caches pin locations with the component. Avoids locking the weak_ptr to the LIB_PART.

-Seth

[Chris Pavlina (pavlina-chris)]

MASSIVE improvement.

[Wayne Stambaugh (stambaughw)]

Seth,

Maybe I overlooked it but I didn't see where the pin end points cache is
getting updated when library symbol link is changed.

On 12/11/2017 6:51 PM, Seth Hillbrand wrote:
> Chris-
>
> Would you mind testing this patch to see if it resolves your speed
> issue?
>
> This caches pin locations with the component. Avoids locking the
> weak_ptr to the LIB_PART.
>
> -Seth
>
> ** Patch added: "0001-Optimizing-speed-of-sch_component-pin-references.patch"
> https://bugs.launchpad.net/kicad/+bug/1737363/+attachment/5021513/+files/0001-Optimizing-speed-of-sch_component-pin-references.patch
>

[Seth Hillbrand (sethh)]

I was debating whether to put an explicit update call or not. The library update sends a kiway SCH_REFRESH message, which triggers a call to TestDanglingEnds. The first step of this is to call GetEndPoints, where the pin endpoints cache gets updated.

[Wayne Stambaugh (stambaughw)]

The library symbol link can also be changed directly using the schematic
symbol properties dialog.

On 12/12/2017 9:06 AM, Seth Hillbrand wrote:
> I was debating whether to put an explicit update call or not. The library update sends a kiway SCH_REFRESH message, which triggers a call to TestDanglingEnds. The first step of this is to call GetEndPoints, where the pin endpoints cache gets updated.
>

[Seth Hillbrand (sethh)]

True. But that also hits the frame's refresh method, which calls the same path and updates the dangling ends and therefore the pin cache.

[Wayne Stambaugh (stambaughw)]

Is this patch going to fix this bug report? If so, I will fix the
commit message and get it merged.

On 12/12/2017 10:43 AM, Seth Hillbrand wrote:
> True. But that also hits the frame's refresh method, which calls the
> same path and updates the dangling ends and therefore the pin cache.
>

[Seth Hillbrand (sethh)]

Wayne-

I gave your comment a bit more thought. I think it is probably better to have an explicit call to update the pin cache, even at the expense of an extra lock/unlock cycle. I've adjusted the patch to place the pin update call in SCH_COMPONENT::ResolveAll. This is explicitly called when we need to ensure the component libid is valid, so it is the logical place to update the pin cache as well.

Attached is the corrected patch.

[Seth Hillbrand (sethh)]

AND... just when I thought I covered the cases...

When changing the footprint reference (not editing the footprint), UpdateSymbolLinks doesn't call ResolveAll.

This patch covers this last case, forcing UpdateSymbolLinks to just update the pin cache if it doesn't need a full library resolve.

Should be final.

[Wayne Stambaugh (stambaughw)]

On 12/12/2017 3:01 PM, Seth Hillbrand wrote:
> AND... just when I thought I covered the cases...
>
> When changing the footprint reference (not editing the footprint),
> UpdateSymbolLinks doesn't call ResolveAll.
>
> This patch covers this last case, forcing UpdateSymbolLinks to just
> update the pin cache if it doesn't need a full library resolve.
>
> Should be final.

Famous last words ;)

>
> ** Patch added: "0001-Optimizing-speed-of-sch_component-pin-references.patch"
> https://bugs.launchpad.net/kicad/+bug/1737363/+attachment/5021842/+files/0001-Optimizing-speed-of-sch_component-pin-references.patch
>

[KiCad Janitor (kicad-janitor)]

Fixed in revision 8e764f85a41e885934c4070aec355fed90f87d44
https://git.launchpad.net/kicad/patch/?id=8e764f85a41e885934c4070aec355fed90f87d44

[Wayne Stambaugh (stambaughw)]

Seth,

This looks right so I merged your patch.

Thanks,

Wayne

On 12/12/2017 03:01 PM, Seth Hillbrand wrote:
> AND... just when I thought I covered the cases...
>
> When changing the footprint reference (not editing the footprint),
> UpdateSymbolLinks doesn't call ResolveAll.
>
> This patch covers this last case, forcing UpdateSymbolLinks to just
> update the pin cache if it doesn't need a full library resolve.
>
> Should be final.
>
> ** Patch added: "0001-Optimizing-speed-of-sch_component-pin-references.patch"
> https://bugs.launchpad.net/kicad/+bug/1737363/+attachment/5021842/+files/0001-Optimizing-speed-of-sch_component-pin-references.patch
>