GUI application built with Racket 6.3 is slooooow to start

[Alex Harsanyi]

I finally got my application [1] to build using Racket 6.3 after working around the problem with using plot-snip% objects [2].  Unfortunately, now while building the application, Racket 6.3 uses between 1.5 and 3 Gb of RAM, while Racket 6.1.1 only used between 0.5 and 0.8 Gb or ram to do the same thing.  Once built, the application takes about 60 seconds or more to start up, compared to the version built using Racket 6.1.1 which takes about 3-5 seconds to start up.  Once it started up, the application is just as responsive as the previous version, so the problem is only during startup.

For reference, I'm using 64bit Racket versions on a Windows machine.

Could someone provide some starting points for trying to diagnose the cause of this?   I'm not really familiar with the Racket internals.

BTW, if anyone wants to build the application using Racket 6.1.1, you have to drop the last two commits of the master branch, as they contain the workaround to make the code work in Racket 6.3.

Thanks,
Alex.

[1] https://github.com/alex-hhh/ActivityLog2
[2] https://groups.google.com/forum/#!searchin/racket-dev/plot/racket-dev/wOgQ9gdWqfQ/sRwkfGBMXyIJ

[Robby Findler]

It looks like there are some changes in the way that the typed/untyped
boundaries are (judging from those two last commits). Maybe try
running the contract profiler on the startup portion and see if it
gives us a lead?

Robby

> --
> You received this message because you are subscribed to the Google Groups
> "Racket Developers" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to racket-dev+...@googlegroups.com.
> To post to this group, send email to racke...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/racket-dev/47433de9-48b8-44b2-adfd-e4939db5394a%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Matthew Flatt]

The start-up problem is a combination of two things:

* Starting with v6.3, the `plot` library is implemented with typed
classes. The compile-time part of typed classes is big and
expensive.

* The run-time system is over-eager in forcing compile-time code in
response to a `dynamic-require` of already-compiled code, so that
expensive compile-time part gets run in your generated executable.

The last bullet has been fixed for the next release, so you could try a
snapshot build. (The most recent snapshot build failed on Windows for
boring reasons, but the previous build is still available through the
"last-success" links.) Unfortunately, I don't have an easy workaround
for v6.3.


The change to `plot` also explains why generating an executable takes
so much more time and space than before. In that case, the compile-time
is needed, so it can't be skipped, but various caches help. There's
still room for improvement in the executable-generator so that it
doesn't re-expand modules so much, but I'll have to think about it
more.


Finally, I think you can avoid some unwanted influence by DrRacket and
its debugging mode on the generated executable by wrapping the call
to `create-embedding-executable` with

(parameterize ([use-compiled-file-paths (list "compiled")])
....)

It's also a good idea to pass

#:expand-namespace (make-base-namespace)

to `create-embedding-executable`.

[Alex Harsanyi]

Hi Matthew,

Thanks for providing the suggestions.

When using Racket 6.3.0.11 (built on 2016-01-06) and your recommended changes
to calling create-embedded-executable, I get a built application that starts
up in the same amount of time as the one built with 6.1.1.  Unfortunately, the
memory use while compiling is still high: seems to me to be about the same as
for 6.3, but I'm only watching the number in the task manager.  Incidentally,
because it uses about 3Gb of ram, the build is constantly swapping, making it
extremely slow.  The difference in build times is huge (see below).  In both
cases, I had only DrRacket running on a Core i7 w/ 8Gb of Ram:

Welcome to DrRacket, version 6.3.0.11--2016-01-06(4b266f1/a) [3m].
Language: racket; memory limit: 2048 MB.
> (time (build-app))
cpu time: 439953 real time: 442172 gc time: 120471

Welcome to DrRacket, version 6.1.1 [3m].
Language: racket; memory limit: 2048 MB.
> (time (build-app))
cpu time: 174812 real time: 177352 gc time: 77731

On a somewhat related note, there are two additional issues I noticed with the executables produced by the Racket compiler (across several Racket versions, but also present in the last pre-release build).

First problem is that although the compilation succeeds with no error message, the application fails to run with a message like:

link: bad variable linkage;
 reference to a variable that has the wrong procedure or structure-type shape
  reference phase level: 0
  variable module: '#%embedded:g498165:sport-charms
  variable phase: 0
  reference in module: '#%embedded:g477831:fmt-util
  in: val->pct-of-max
  errortrace...:
  context...:
   #%embedded:g477831:fmt-util: [running body]
   #%embedded:g473202:al-widgets: [traversing imports]
   #%embedded:g471367:edit-session-summary: [traversing imports]
   #%embedded:g469250:activity-edit: [traversing imports]
   #%embedded:g450111:toplevel: [traversing imports]
   #%embedded:g434256:activity-log-main: [traversing imports]
   run: [traversing imports]
   loop

I can fix this by cleaning the "compiled" folders, but I would expect the compiler to either re-build dependencies or flag a compilation error, but it does neither.

Second, the resulting application seg-faults, sometimes at startup sometimes during importing sport activties.  I have the crash dumps but cannot make any sense of them, as I have no PDB's for libracket and I'm not familiar with the internals.  If you are interested, I can make them available.

Best Regards,
Alex.

[Matthew Flatt]

At Sat, 9 Jan 2016 18:58:19 -0800 (PST), Alex Harsanyi wrote:
> When using Racket 6.3.0.11 (built on 2016-01-06) and your recommended
> changes to calling create-embedded-executable, I get a built
> application that starts up in the same amount of time as the one
> built with 6.1.1. Unfortunately, the memory use while compiling is
> still high: seems to me to be about the same as for 6.3, but I'm only
> watching the number in the task manager. Incidentally, because it
> uses about 3Gb of ram, the build is constantly swapping, making it
> extremely slow.

The TR team is working on performance improvements in the TR compiler
and the comple-time information it generates, and there's also room for
improvement in the way that `raco exe` works. Unfortunately, though, my
guess is that it will be a while before build times improve for your
application.

> On a somewhat related note, there are two additional issues I noticed with
> the executables produced by the Racket compiler (across several Racket
> versions, but also present in the last pre-release build).
>
> First problem is that although the compilation succeeds with no error
> message, the application fails to run with a message like:
>
> link: bad variable linkage;

Does that still happen with the extra `parameterize` that I suggested
previously? If so, probably DrRacket is influencing
`create-embedding-executable` in some other way that I didn't notice.

> Second, the resulting application seg-faults, sometimes at startup
> sometimes during importing sport activties. I have the crash dumps but
> cannot make any sense of them, as I have no PDB's for libracket and I'm not
> familiar with the internals. If you are interested, I can make them
> available.

Any information you have would be useful. If there's some way I can run
the application to reliably trigger a crash, that would also be useful.

[Alex Harsanyi]

On Sunday, January 10, 2016 at 11:14:23 AM UTC+8, mflatt wrote:

At Sat, 9 Jan 2016 18:58:19 -0800 (PST), Alex Harsanyi wrote:
> When using Racket 6.3.0.11 (built on 2016-01-06) and your recommended
> changes to calling create-embedded-executable, I get a built
> application that starts up in the same amount of time as the one
> built with 6.1.1. Unfortunately, the memory use while compiling is
> still high: seems to me to be about the same as for 6.3, but I'm only
> watching the number in the task manager. Incidentally, because it
> uses about 3Gb of ram, the build is constantly swapping, making it
> extremely slow.

The TR team is working on performance improvements in the TR compiler
and the comple-time information it generates, and there's also room for
improvement in the way that `raco exe` works. Unfortunately, though, my
guess is that it will be a while before build times improve for your
application.

Thanks for working on it.
 

> On a somewhat related note, there are two additional issues I noticed with
> the executables produced by the Racket compiler (across several Racket
> versions, but also present in the last pre-release build).
>
> First problem is that although the compilation succeeds with no error
> message, the application fails to run with a message like:
>
> link: bad variable linkage;

Does that still happen with the extra `parameterize` that I suggested
previously? If so, probably DrRacket is influencing
`create-embedding-executable` in some other way that I didn't notice.

No, it did not.  However, at least with racket 6.1.1 this type of problem was hard to reproduce, but  I commited the change to the code base and will monitor if this is happening in the future.
 

> Second, the resulting application seg-faults, sometimes at startup
> sometimes during importing sport activties.  I have the crash dumps but
> cannot make any sense of them, as I have no PDB's for libracket and I'm not
> familiar with the internals.  If you are interested, I can make them
> available.

Any information you have would be useful. If there's some way I can run
the application to reliably trigger a crash, that would also be useful.

Unfortunately  I don't have a reliable way to trigger a crash.  There are two situations when a crash happens: at startup -- this happens a few times a week (I use this application daily), just as I start the application.  The second type of crash is  just after importing some fitness activities -- this is more rare.  In both cases the application crashes at system level (no Racket exception is thrown).

I put some crash dumps here:

https://drive.google.com/folderview?id=0B5h4XOdkim72eVdqRnY5MWNoUUU&usp=sharing

The first crash is:

Unhandled exception at 0x00007FFE8DD2324A (ntdll.dll) in ActivityLog2.dmp: 0xC0150014: The activation context activation stack for the running thread of execution is corrupt (parameters: 0x0000000000A00830, 0x0000000000846270, 0x0000000000846270, 0x000000001B6ED300).

Call stack is:
     ntdll.dll!RtlActivateActivationContextUnsafeFast()    Unknown
     user32.dll!UserCallWinProcCheckWow ()    Unknown
     user32.dll!DispatchMessageWorker ()    Unknown
     libracket3m_9xtjc8.dll!000000018033bc43()    Unknown
     libracket3m_9xtjc8.dll!000000018000165f()    Unknown
     libracket3m_9xtjc8.dll!0000000180018448()    Unknown
     libracket3m_9xtjc8.dll!0000000180018679()    Unknown

The second crash type is an access violation (segfault).

I 'm thinking of adding some logging to the code to try to determine what  Racket code is running when the crash happens. Are there some recommendations on how to debug these types of crashes?  Is there a way to map from a crash dump location to the running Racket code?

Best Regards,
Alex.