getAvailableCoordianteReferenceSystems() log info message on success which spam console

[khanaffan]

Describe the bug
GeoCoord logger spam info message Successfully loaded GCS file ... when getAvailableCoordianteReferenceSystems() is called.

If this message is needed it should be Trace or Debug level and not info.

To Reproduce
Steps to reproduce the behavior:

1. Call getAvailableCoordianteReferenceSystems() hundreds of times. Change log level to trace or debug for this log error

Expected behavior

Show not spam info log messages on success for a function that get called hundreds of time.

Screenshots

Desktop (please complete the applicable information):

• OS: all
• chrome
• iTwin.js Version 4.10

Reported by @karolis-zukauskas opensiteplus

[karolis-zukauskas]

For context, starting up OpenSite+ I get 36477 of these log entries. Timing getAvailableCoordinateReferenceSystems():

• With info logs enabled ~22 seconds
• With info logs disabled ~2-3 seconds

I don't know if this function is supposed to take 2-3 seconds - could it be that all the 36K jumps from native to js to call Logger.logInfo(...) responsible for this execution time?

[kckst8]

@iTwin/itwinjs-core are there general guidelines for logging (i.e. what type of data should be logged for each log level)? I feel like this is likely to continue if left up to developer preference

[ben-polinsky]

General issue for this function's performance #7643

[ben-polinsky]

• With info logs enabled ~22 seconds

• With info logs disabled ~2-3 seconds

I'll alter the log level, but I cannot yet minimally replicate this time discrepancy.

[pmconne]

I cannot yet minimally replicate this time discrepancy.

Are you testing in Karolis' app? Maybe it or Mango has customized the logger.

[ben-polinsky]

Are you testing in Karolis' app? Maybe it or Mango has customized the logger.

Have not. I'll give it a go.

[ben-polinsky]

In app, I've reproduced a similar delay to Karolis when flipping on info level logging:

w/o logging: 1.704s
w/ logging: 8.909s

[tcobbs-bentley]

@ben-polinsky If this is app-specific, you might want to check if there are custom log functions being passed into Logger.initialize on the backend.

[ben-polinsky]

I'd definitely look into logging setup. @johnnyd710 have you tracked any performance issues w/r/t winston or other parts of your integration?

[johnnyd710]

I'd definitely look into logging setup. @johnnyd710 have you tracked any performance issues w/r/t winston or other parts of your integration?

I just did a quick analysis of OpenSite+. With verbose logging, it takes a very long time because we are writing all those thousands of logging calls to the console and to a file. I'd hope Winston was smart enough to group/batch and write them all at once instead of one-at-a-time but it doesn't seem so. Without verbose logging, it spends 2.15 seconds inside this function. I can't see inside the native function from chrome developer tools. I attached the trace without versbose logging and with.

with-verbose-logging.cpuprofile

without-verbose-logging.cpuprofile