Logging is holding up the request thread?

[stephenplusplus]

From @bmenasha on June 27, 2017 20:41

• Node.js version: v8.1.1
• npm version: 5.04
• google-cloud-node version: 0.4.1 (@google-cloud/logging-winston)

  Steps to reproduce

var winston = require('winston');
require('@google-cloud/logging-winston');
winston.add(transport, {projectId: 'redacted', level: 'debug', name: 'mylogger',  logName: 'nodjs.log'});

when I examine the requests in cloud trace it's clear that the request is being held up by calls to the logging API, worse, there are MULTIPLE calls to the cloud logging api in a single request. This results in some pretty poor performance. Consider:

![selection_999 136](https://user-images.githubusercontent.com/6843728/27608499-c7ec1e3e-5b55-11e7-8946-e2402e38c3fb.png)

Here is a stackdtrace from one of these logging calls:

clientMethodTrace [as writeLogEntries] (node_modules/@google-cloud/trace-agent/src/plugins/plugin-grpc.js:67:22)
<anonymous function> (node_modules/@google-cloud/logging/src/v2/logging_service_v2_client.js:137:51)
timeoutFunc [as _apiCall] (node_modules/google-gax/lib/api_callable.js:177:12)
Task.run [as run] (node_modules/google-gax/lib/bundling.js:202:29)
BundleExecutor._runNow [as _runNow] (node_modules/google-gax/lib/bundling.js:451:8)
<anonymous function> (node_modules/google-gax/lib/bundling.js:390:12)
_onTimeout (node_modules/async-listener/glue.js:188:31)
ontimeout (timers.js:488:11)
tryOnTimeout (timers.js:323:5)
listOnTimeout (timers.js:283:5)

Perhaps this is due to the VERY aggressive 10ms bundling in the gax config file:

        "WriteLogEntries": {
          "timeout_millis": 30000,
          "retry_codes_name": "non_idempotent",
          "retry_params_name": "default",
          "bundling": {
            "element_count_threshold": 100,
            "request_byte_threshold": 1024,
            "delay_threshold_millis": 10
          }
        },

I think we should have better defaults (batch/bundle more) and also find a way to send these log (and trace) requests asynchronously so they don't block the current request from returning. Thanks

Copied from original issue: GoogleCloudPlatform/google-cloud-node#2416

[stephenplusplus]

From @lukesneeringer on July 5, 2017 15:14

@bmenasha Thank you for reporting this (and sorry it took so long to get back to you on it).

I am guessing delay_threshold_millis should have been 10,000 instead of 10, but I am not the most familiar with this module. Would that make sense in your mind?

I also agree that this should not block.

[stephenplusplus]

From @bmenasha on July 6, 2017 3:48

Would that make sense in your mind?

Sure.

[stephenplusplus]

@lukesneeringer should we go ahead and update this value, or is there someone we need to ping first?

[stephenplusplus]

From @landrito on August 9, 2017 22:28

Updating this gax value would involve changing it at the generator config level for logging. I'd like to invite @pongad to chime in on changing this to 10,000 from 10.

[stephenplusplus]

From @pongad on August 10, 2017 5:6

I'm not familiar with how bundling is implemented in node. I'm a little confused that it blocks. Node in single threaded, so if you block waiting for either 100 elements in the batch or 10ms to pass before sending the request, you'll always wait 10ms since nothing can add more elements into the batch right? Did I misunderstand?

Or maybe we're waiting to send one batch because there's another batch pending or something...?

[stephenplusplus]

From @ofrobots on August 14, 2017 18:37

A few points here:

• Logging is not synchronous, but you can write business logic to wait for logging to finish before proceeding with your business logic. Looking at the screenshot @bmenasha posted, you will notice that the first call to logging is done in parallel with the rest of the business logic, while the second call is being done in a way that the final mongo-update is dependent on the logging call to finish. @bmenasha: you should be able to avoid this dependency in your own code by moving the mongo-update logic outside of the callback from log.write. Let me know if my guesses here are incorrect.
• Unless I am mistaken, the default value at present seems to be 50ms rather than 10ms: https://github.com/GoogleCloudPlatform/google-cloud-node/blob/118b622db780e25e63bf5e19fefa16d9782a10ab/packages/logging/src/v2/logging_service_v2_client_config.json#L44. @bmenasha do you want to move to a more recent version of the logging library? Also note that you may want to use individual modules (e.g. @google-cloud/logging) rather than using the meta-package.
• On increasing the default value, there is a trade-off in the bundling latency. If your process crashes before the logs have been flushed, you will lose those logs. I'm strongly -1 on using 10 seconds as the default. 50ms sounds like a reasonable number to me. Note that changing this value will have no impact if these expensive logging calls are user initiated (as is my guess based on the traces).

@pongad Node is concurrent through asynchronous APIs. Network calls do not block user code, but you can write code that waits for the network call to finish before proceeding.

[stephenplusplus]

From @ofrobots on August 14, 2017 18:43

@bmenasha I also noticed that your logging calls seem very expensive – that doesn't look normal, unless you are logging large amounts of data. Can you verify that is the case? Also, are you using the logging library directly or are you using the higher level libraries (google-cloud/logging-winston, google-cloud/logging-bunyan)?

[stephenplusplus]

@bmenasha @ofrobots just for clarity-- is there a bug here?

[stephenplusplus]

From @ofrobots on September 1, 2017 22:37

I don't believe there is a bug here, but It would be good to get input from @bmenasha to make sure I am not making any incorrect assumptions.

[stephenplusplus]

I'm going to close, given the age of the issue. If there is still work left to be done, please let me know, and we will re-open.