Jaeger Exporter causing huge CPU spike

Users Dgraph
1 
(pprof) top20 --cum
Showing nodes accounting for 48.43s, 62.77% of 77.15s total
Dropped 343 nodes (cum <= 0.39s)
Showing top 20 nodes out of 63
      flat  flat%   sum%        cum   cum%
         0     0%     0%     44.40s 57.55%  google.golang.org/api/support/bundler.(*Bundler).startFlushLocked.func1
     0.17s  0.22%  0.22%     44.08s 57.14%  google.golang.org/api/support/bundler.(*Bundler).acquire
     0.42s  0.54%  0.76%     43.23s 56.03%  sync.(*Cond).Wait
    33.11s 42.92% 43.68%     33.11s 42.92%  runtime.futex
     0.25s  0.32% 44.01%     29.68s 38.47%  runtime.mcall
     0.82s  1.06% 45.07%     29.49s 38.22%  sync.(*Mutex).Lock
     0.43s  0.56% 45.63%     29.33s 38.02%  runtime.park_m
     0.22s  0.29% 45.91%     28.32s 36.71%  sync.runtime_SemacquireMutex
     0.65s  0.84% 46.75%     28.10s 36.42%  runtime.semacquire1
     2.85s  3.69% 50.45%     24.75s 32.08%  runtime.lock
     0.13s  0.17% 50.62%     20.55s 26.64%  runtime.futexsleep
     0.44s  0.57% 51.19%     16.90s 21.91%  runtime.schedule
     3.52s  4.56% 55.75%     15.37s 19.92%  runtime.findrunnable
     2.60s  3.37% 59.12%     14.70s 19.05%  runtime.unlock
     0.04s 0.052% 59.17%     12.73s 16.50%  runtime.futexwakeup
     0.06s 0.078% 59.25%     11.92s 15.45%  runtime.parkunlock_c
     0.37s  0.48% 59.73%      9.99s 12.95%  sync.(*Mutex).Unlock
     0.03s 0.039% 59.77%      9.62s 12.47%  sync.runtime_Semrelease
     0.46s   0.6% 60.36%      9.59s 12.43%  runtime.semrelease1
     1.86s  2.41% 62.77%      7.50s  9.72%  runtime.runqsteal

Digging deeper:

(pprof) list startFlushLocked.func1
Total: 1.29mins
ROUTINE ======================== google.golang.org/api/support/bundler.(*Bundler).startFlushLocked.func1 in /home/mrjn/go/src/google.golang.org/api/support/bundler/bundler.go
         0     44.40s (flat, cum) 57.55% of Total
         .          .    266:	go func() {
         .          .    267:		defer func() {
         .          .    268:			b.sem.Release(int64(bun.size))
         .          .    269:			b.release(ticket)
         .          .    270:		}()
         .     44.08s    271:		b.acquire(ticket)
         .       20ms    272:		b.handler(bun.items.Interface())
         .      300ms    273:	}()
         .          .    274:}
         .          .    275:
         .          .    276:// acquire blocks until ticket is the next to be served, then returns. In order for N
         .          .    277:// acquire calls to return, the tickets must be in the range [0, N). A ticket must
         .          .    278:// not be presented to acquire more than once.
ROUTINE ======================== google.golang.org/api/support/bundler.(*Bundler).startFlushLocked.func1.1 in /home/mrjn/go/src/google.golang.org/api/support/bundler/bundler.go
         0      300ms (flat, cum)  0.39% of Total
         .          .    264:	ticket := b.nextTicket
         .          .    265:	b.nextTicket++
         .          .    266:	go func() {
         .          .    267:		defer func() {
         .          .    268:			b.sem.Release(int64(bun.size))
         .      300ms    269:			b.release(ticket)
         .          .    270:		}()
         .          .    271:		b.acquire(ticket)
         .          .    272:		b.handler(bun.items.Interface())
         .          .    273:	}()
         .          .    274:}
2

Thanks for this report Manish!

This seems to be a problem with a library that we import https://godoc.org/google.golang.org/api/support/bundler to help with bundling/batching data before exporting
So a couple of questions:
a) What version of Go is this? Seems like Go1.11 to me, please correct me.
b) What OS is this? Looks like Linux to me
c) What scenario best describes the time of reproduction? No traces coming? A flood of traces? Normal load? – I ask because there seems to be a lock that’s blocked

In discussions with other folks, we’ve had various proposals for replacement of the bundler e.g. a sharder by n goroutines to reduce on the lock contention that that library experiences.

Thank you.

3

a. Go1.11
b. Linux/Ubuntu
c. So, we restarted a server. And after it came back up, it just went into a high drive mode, where it started consuming a lot of CPU. And doing a profile showed what I pasted above. After some time, it went back to normal.

4

Thank you for the response Manish!

My postulation here is that on server restart and wakeup there was a flood of traces being produced and since that Jaeger exporter doesn’t allow one to configure the bundler’s BundleCountThreshold, it uses a very low threshold of only 10 google-api-go-client/bundler.go at 78b596aa1e71326943165617fdb108dd18b34dbf · googleapis/google-api-go-client · GitHub

which will cause a huge amount of goroutines and due to load balancing by the runtime scheduler over your cores, it consumes a lot of CPU. Eventually the uploading/consumption rate catches up to the production rate and the amount of goroutines stabilizes. A simple experiment to experience this is by running these Go programs and monitoring your CPU usage and eventually causing a core dump with Ctrl + \ for which for “Scenario 1” you’ll see many goroutines tripping on startFlushLocked. Interesting also that the first goroutine is the one being tripped up on:

Scenario 1: (postulated current scenario)

package main

import (
	"net/http"
	"time"

	"google.golang.org/api/support/bundler"
)

func main() {
	bdlr := bundler.NewBundler((*int)(nil), func(bundle interface{}) {
		sl := bundle.([]*int)
		if len(sl) == 0 {
			panic("empty slice")
		}
	})

	for {
		for i := 0; i < 1e5; i++ {
			bdlr.Add(&i, 1)
		}
		<-time.After(5 * time.Second)
	}

	// Just using this instead of: for {}
	http.ListenAndServe(":8888", nil)
}

Scenario 2: (ideal with sufficient bundling count to enable trace production to catch up with consumption rate):

package main

import (
	"net/http"
	"time"

	"google.golang.org/api/support/bundler"
)

func main() {
	bdlr := bundler.NewBundler((*int)(nil), func(bundle interface{}) {
		sl := bundle.([]*int)
		if len(sl) == 0 {
			panic("empty slice")
		}
	})
	bdlr.BundleCountThreshold = 1e3

	for {
		for i := 0; i < 1e5; i++ {
			bdlr.Add(&i, 1)
		}
		<-time.After(5 * time.Second)
	}

	// Just using this instead of: for {}
	http.ListenAndServe(":8888", nil)
}

Remedies;

  • I’d highly suggest using the agent opencensus.io/service/components/agent/ and use the ocagent-exporter which will replace the Jaeger exporter but also will enable you to horizontally scale your deployments Dgraph servers if using the Prometheus exporter and is literally a drop-in replacement for both exporters like this:
	oce, err := ocagent.NewExporter(
		ocagent.WithInsecure(),
		ocagent.WithReconnectionPeriod(5 * time.Second),
		ocagent.WithAddress("localhost:55678"), // Only included here for demo purposes.
		ocagent.WithServiceName("ocagent-go-example"))
	if err != nil {
		log.Fatalf("Failed to create ocagent-exporter: %v", err)
	}
	trace.RegisterExporter(oce)
	view.RegisterExporter(oce)

I’ve talked to folks who use Prometheus and there are issues during scraping cycles with Prometheus’ client.

Also the ocagent-go-exporter has a bundler default of 300 which is a simple approximation for a very high traffic application. If your server creates spans at say 3,000 QPS, in a second, exporting will be invoked 10 times only instead of the current 300 times – this is very reasonable for various scenarios including startup with a flood of spans.

The agent will also ensure that your customers deploy the agent as a side car once in their entire cloud/cluster and change their export configurations without having to stop their Dgraph servers, they don’t need to have a backend running before their applications run, etc…

Hope this helps and I look forward to hearing back from you.

Thank you!

1 Like