hie-bios takes **long** time when full path specified in hie.yaml

[mouse07410]

MacOS Catalina 10.15.4, Xcode-11.4, Cabal-3.2.0.0 (Hackage, not GitHub repo), Stack-2.1.3, current VSCode, current Haskell Language Server (from VSCode marketplace), current master of HIE.

I got a problem.

With the workaround proposed in #1727, my project https://github.com/mouse07410/Str2Split.git works, and does not show false errors (unless you count the hlint insistence on re-doing $ do ;):

However, whenever I open the .hs files from this project, it takes a long (compared to, e.g., how it used to be with Stack) time. I see "Initializing Cabal project" status message on the bottom bar of VSCode window, and after half a minute or so that message disappears, and the project is ready. This re-initialization repeats for every .hs file I open. And if I close a file and re-open it again, it again re-initializes, with the following:

If I switch this project to Stack and replace hie.yaml content with

cradle:
  stack:

the performance returns (i.e., initialization when the project is opened is reasonably fast, and there is no re-initialization as I open and close .hs files). I suspect performance would return if I do the same with Cabal in hie.yaml. But now I'm getting two errors regarding Hspec framework:

Could not load module 'Test.Hspec'
It is a member of the hidden package 'hspec-2.7.1'.
You can run ':set -package hspec' to expose it.
(Note: this unloads all the modules in the current scope.)
Use -v (or `set -v` in ghci) to see a list of the files searched for.  bios[2,1]
and the same message for Test.QuickCheck.

If I create an analog of the workaround from #1727 for Stack (see hie.yaml-stack in the project), the above error disappears, but performance drops significantly - like with Cabal.

In case it matters - the problems started after I added Hspec to the test/Spec.hs. Before that I did not seem to even need the #1727 workaround.

Is there a workaround or fix for this quite annoying delay problem?

[mouse07410]

Ping...?

[jneira]

Hi, maybe comparing the hie log between implicit stack cradle (cradle: stack:) and the explicit one (hie.yaml-stack) could b euseful to see what hie is actually doing in that extra delay.

[mouse07410]

maybe comparing the hie log...

Could you please point me at where I can find that log? And whether I need to set anything to have that log produced/recorded?

[jneira]

If you use vcode f.e. the output of stderr and stdout is displayed in the output pane, you will have to open the hs file before

Usually we will need set the verbose mode, changing the vscode option:

"languageServerHaskell.trace.server": "verbose"

You also can inform the file where do you want to log:

"languageServerHaskell.logFile": "C:\\TEMP\\hie.log"

and the stdout will be writen there (stderr will continue present in the vscode pane)

[mouse07410]

First, I think it's really bad that HIE crashes if the specified log file doesn't exist, instead of just creating it!

[hie-wrapper: ${workspaceFolder}/hie.log: openFile: does not exist (No such file or directory)
[Info  - 4:01:58 PM] Connection to server got closed. Server will restart.
hie-wrapper: ${workspaceFolder}/hie.log: openFile: does not exist (No such file or directory)
[Info  - 4:01:59 PM] Connection to server got closed. Server will restart.
. . . . .

Second - shouldn't it respect VSCode variables convention as specified in https://code.visualstudio.com/docs/editor/variables-reference ?

Now, despite setting trace to verbose:

and the log file to

the above log file is empty, and the Output window shows nothing that I could make sense of:

Using hie version: Version 1.3 x86_64 ghc-8.8.3
Using hoogle db at: /Users/ur20980/.hoogle/default-haskell-5.0.17.hoo
[Error - 4:11:48 PM] haskell-lsp:no handler for. Object (fromList [("jsonrpc",String "2.0"),("params",Object (fromList [("value",String "off")])),("method",String "$/setTraceNotification")])
[Error - 4:12:04 PM] haskell-lsp:no handler for. Object (fromList [("jsonrpc",String "2.0"),("params",Object (fromList [("value",String "off")])),("method",String "$/setTraceNotification")])

The above is with the "explicit" hie.yaml.

Here's what's happening when I reduce it to

cradle:
  cabal:

After loading Lib.hs:

And after opening Spec.hs:

hie.log remains empty!

[jneira]

Mmmm i think your settings are not being applied, concretely /User/urxxx/hie.log is not taking in account (or you tested it with ${workspaceFolder}/hie.log?). So it is not able to find a folder named ${workspaceFolder} to open or create a file; maybe it should create the folder (although in this case it would be incorrect).

Second - shouldn't it respect VSCode variables convention as specified in https://code.visualstudio.com/docs/editor/variables-reference ?

It should do it, maybe it worths open an issue in the vscode extension project: https://github.com/alanz/vscode-hie-server/issues

And it seems it is using "off" as trace option, instead "verbose". The log in the output panel is the one you got if you set "off".

It is quite strange, i am not aware that those options had not been applied correctly until now. I cant reproduce it in windows. Does it happen if you set project vs user settings?

[mouse07410]

or you tested it with ${workspaceFolder}/hie.log?

After I saw the HIE server crashing with that setting, I switched to /User/urxxx/hie.log, and the server stopped crashing - though it never put anything into that file.

Does it happen if you set project vs user settings?

How?

[jneira]

There are two tabs in the settings pane, one for user(global) scope and other for override them for the actual project (workspace).
Are you using a custom hie-wrapper? It could be one of the causes of the lost arguments

[mouse07410]

Are you using a custom hie-wrapper? It could be one of the causes of the lost arguments

Oh no, I don't.

[mouse07410]

OK, I found config error on my end (somehow, Liquid got enabled?!), and logging became better.

For

# target examples https://cabal.readthedocs.io/en/latest/cabal-commands.html#cabal-v2-build
cradle:
  cabal:
    - path: "./"
      component: "lib:Str2Split"

    - path: "./test/"
      component: "test:Str2Split-test"
      
    - path: "./app/"
      component: "exe:Str2Split-exe"

hie.log: hie-full.log.txt
Update: Uploaded corrected hie-full.log file.

For

# target examples https://cabal.readthedocs.io/en/latest/cabal-commands.html#cabal-v2-build
cradle:
  cabal:

hie.log: hie-basic.log.txt

Hope it can point you at the problem(s).

[mouse07410]

Ping...?

[jneira]

Hi, i've been taking a look to both logs, i'll reproduce the relevant part of the slow init:

2020-05-01 22:36:35.348674 [ThreadId 69] - Warning: The package list for 'll-skete' is 18 days old.
2020-05-01 22:36:35.348754 [ThreadId 69] - Run 'cabal update' to get the latest list of available packages.
2020-05-01 22:36:35.531629 [ThreadId 71] - Resolving dependencies...
2020-05-01 22:36:35.962752 [ThreadId 71] - Build profile: -w ghc-8.8.3 -O1
2020-05-01 22:36:35.96285 [ThreadId 71] - In order, the following will be built (use -v for more details):
2020-05-01 22:36:35.962888 [ThreadId 71] -  - Str2Split-0.1.0.0 (lib) (configuration changed)
2020-05-01 22:36:35.962921 [ThreadId 71] -  - Str2Split-0.1.0.0 (test:Str2Split-test) (configuration changed)
2020-05-01 22:36:36.199256 [ThreadId 71] - Configuring library for Str2Split-0.1.0.0..
2020-05-01 22:36:40.217462 [ThreadId 71] - Preprocessing library for Str2Split-0.1.0.0..
2020-05-01 22:36:40.218199 [ThreadId 71] - Building library for Str2Split-0.1.0.0..
2020-05-01 22:36:42.136937 [ThreadId 71] - Preprocessing library for Str2Split-0.1.0.0..
2020-05-01 22:36:42.138311 [ThreadId 71] - Running Haddock on library for Str2Split-0.1.0.0..
2020-05-01 22:36:43.093656 [ThreadId 71] - Haddock coverage:
2020-05-01 22:36:43.093748 [ThreadId 71] -    0% (  0 /  5) in 'Lib'
2020-05-01 22:36:43.093792 [ThreadId 71] -   Missing documentation for:
2020-05-01 22:36:43.093827 [ThreadId 71] -     Module header
2020-05-01 22:36:43.093863 [ThreadId 71] -     splitStr (src/Lib.hs:12)
2020-05-01 22:36:43.093896 [ThreadId 71] -     chunker (src/Lib.hs:26)
2020-05-01 22:36:43.093934 [ThreadId 71] -     splitMore (src/Lib.hs:29)
2020-05-01 22:36:43.093967 [ThreadId 71] -     splitLess (src/Lib.hs:32)
2020-05-01 22:36:43.156688 [ThreadId 71] - Documentation created:
2020-05-01 22:36:43.156781 [ThreadId 71] - /Users/ur20980/Src/Str2Split/dist-newstyle/build/x86_64-osx/ghc-8.8.3/Str2Split-0.1.0.0/doc/html/Str2Split/index.html
2020-05-01 22:36:43.272949 [ThreadId 71] - Configuring test suite 'Str2Split-test' for Str2Split-0.1.0.0..
2020-05-01 22:36:46.007019 [ThreadId 69] - Warning: The package has an extraneous version range for a dependency on an
2020-05-01 22:36:46.007094 [ThreadId 69] - internal library: Str2Split -any && ==0.1.0.0, Str2Split -any && ==0.1.0.0.
2020-05-01 22:36:46.007121 [ThreadId 69] - This version range includes the current package but isn't needed as the
2020-05-01 22:36:46.007145 [ThreadId 69] - current package's library will always be used.
2020-05-01 22:36:47.024505 [ThreadId 71] - Preprocessing test suite 'Str2Split-test' for Str2Split-0.1.0.0..
2020-05-01 22:36:47.365613 [ThreadId 5] - <--2--{"jsonrpc":"2.0","params":{"value":{"kind":"report","percentage":50,"message":"Main"},"token":2},"method":"$/progress"}
2020-05-01 22:36:47.372771 [ThreadId 66] - Modules in the cradle: ["test/Spec.hs","/Users/ur20980/Src/Str2Split/dist-newstyle/build/x86_64-osx/ghc-8.8.3/Str2Split-0.1.0.0/t/Str2Split-test/build/Str2Split-test/autogen/Paths_Str2Split.hs"]
2020-05-01 22:36:47.37303 [ThreadId 5] - <--2--{"jsonrpc":"2.0","params":{"value":{"kind":"report","percentage":100,"message":"Paths_Str2Split"},"token":2},"method":"$/progress"}
2020-05-01 22:36:47.373525 [ThreadId 66] - Cradle set succesfully

It takes 13 seconds but we have to take in account:

• It triggered a build of the lib with cabal, including an update of the package index (9 seconds)
• It triggers a build of the test component
  Without the cabal update i should be faster.

[mouse07410]

It takes 13 seconds but we have to take in account:

• It triggered a build ...
• ...
  Without the cabal update i should be faster

I don't understand - why does it perform the whole build??? All it seems to need is parsing???

Also, I did not request cabal update - how/why did it get invoked, and how can I avoid it?

Also, consider that this is a very small toy project - I shudder to think what the delay/time lag would be for a real-size project.

[jneira]

Well, hie relies in hie-bios to load a haskell file, and it uses cabal in turn to build the necessary stuff to compile the file succesfully. It basically calls cabal repl target if you use hie.yaml.

Not sure which component triggered the cabal update, from the log i would say that cabal itself. If it is the case i suppose it will have some config option to disable it.

The update delay depends on the hackage index, not on project size. In the example it was the main source of the delay but it is triggered very occasionally and the index is global for all projects.
Otoh the build is cached but the first time you trigger it without cache, it will take more time if the project has many deps and modules.

[mouse07410]

The update delay depends on the hackage index, not on project size. In the example it was the main source of the delay but it is triggered very occasionally and the index is global for all projects.

I'm afraid I don't understand. I observe this insane delay every time I (re-)open a file, without restarting VS Code, let alone anything else. I don't think Hackage index could possibly change between the two consecutive requests to open the same file.

Otoh the build is cached but the first time you trigger it without cache, it will take more time if the project has many deps and modules.

This delay is very consistent, and does not seem to depend on whatever could be cached (or maybe it refuses to cache...?)...

Not sure which component triggered the cabal update, from the log i would say that cabal itself. If it is the case, I suppose it will have some config option to disable it

Let's try it???