High CPU consumption using Coralogx hook with Logrus

[elig-salt]

Hi,
We've connected a hook to a logrus logger, and cpu spiked.
We've profiled and looks like Coralogix Go SDK is responsible for 95% of the CPU time.
Sending the bulk (23%) is understandable - but some 45% goes on formatting.
Can anyone on the Coralogix team advise?
This kind of spike is unacceptable on a client-side running app we're deploying.
Thanks.

[EldarAliiev]

Thanks for the report!
We are investigating your issue.
What do you use for profiling and how much records do you send to Coralogix?

[elig-salt]

Thanks for the quick response.

We're using Go 1.15.8 (latest)

Reproducing:

We write a debug log every 5 seconds using logrus.
Try the following, then attach a Coralogix web hook and see the cpu differences.

We do use fields, and sometimes not just strings

var log = logrus.New()
log.SetFormatter(&logrus.JSONFormatter{})
log.SetOutput(os.Stdout)
log.SetLevel(logrus.DebugLevel)
log.WithFields(logrus.Fields{
	"hello": "world",
	"verisonDate": time.Now(),
}).Info("Hello World Message")

All we did was attach the hook:

CoralogixHook := coralogix.NewCoralogixHook(
		CORALOGIX_PRIVATE_KEY,
		CORALOGIX_APPLICATION_NAME,
		CORALOGIX_SUBSYSTEM_NAME,
	)

// defer CoralogixHook.Close() // No need to close in our case
log.AddHook(CoralogixHook)

Profiling:

1. go get -u github.com/google/pprof
2. Add this to your code:

import  (
_ "net/http/pprof"
)

func RunProfiler() {
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()
}

and make sure to run RunProfiler() somewhere in your code, while keeping the process up.

3. Run :

go tool pprof -http ":9000" -seconds 60 <SOME_RANDOM_NAME> http://localhost:6060/debug/pprof/profile

OR use the console (without the -http ":9000" part)

go tool pprof  -seconds 60 <SOME_RANDOM_NAME> http://localhost:6060/debug/pprof/profile

Then use commands such as: top15, cum, flat, etc.

[EldarAliiev]

We will check and get back to you ASAP.

[EldarAliiev]

We did profiling and benchmarking and cannot reproduce this behavior.
I'll update you when we'll find something else.

[elig-salt]

@EldarAliiev I've create a simple repo that reproduces this:
https://github.com/elig-salt/logrus-coralogix-cpu

[EldarAliiev]

@elig-salt I checked everything with profiler and even without any actions go-coralogix-sdk.(*LoggerManager).Run function takes ~99% of CPU time because it's running as goroutine in separate thread during all time of your program:

[elig-salt]

Thanks for looking into this.
We appreciate it, and would like to be able to use Coralogix as a universal solution across our company.

Regarding your exaplanation -
Unfortunately - This still doesn't explain the radical spike in CPU.

In the original executable we ran when we saw this behavior - we run 7 additional goroutines, each with it's own logic - http requests, files being watched, an actual web server, and more.
The CPU utilization on our side is less than 1%.

That's because a goroutine in itself is not CPU intensive.
Mutexes, loops and and thread synchronization actions, however, can be.

Here is a screenshot of some code I've added to the example I've shared before -
running 3 additional go-routines, each running a for loop - which will each utilize 100%:

Here is the same example without the loop:

So - It's a question of what exactly is running in the goroutine,
and not the fact the goroutine is running.

[EldarAliiev]

@elig-salt we added some fix.
Is this results works for you:

[elig-salt]

Thanks for the effort.
I don't know how this affects CPU until I run the executable on the machine (the picture doesn't show what the executable will use as a percentage of the host machine - it only shows the CPU percentage out of whatever the binary uses).
So looking forward to seeing what changed in the next release of the SDK.