Log statement spamming, causing unresponsive system

Issues Dgraph
1

Report a Dgraph Bug

What version of Dgraph are you using?

Dgraph Version 
$ dgraph version
 
# dgraph version
[Decoder]: Using assembly version of decoder
Page Size: 4096

Dgraph version   : v20.11.2
Dgraph codename  : tchalla-2
Dgraph SHA-256   : 0153cb8d3941ad5ad107e395b347e8d930a0b4ead6f4524521f7a525a9699167
Commit SHA-1     : 94f3a0430
Commit timestamp : 2021-02-23 13:07:17 +0530
Branch           : HEAD
Go version       : go1.15.5
jemalloc enabled : true

Have you tried reproducing the issue with the latest release?

no

What is the hardware spec (RAM, OS)?

k8s - 1alpha(no ha) 3zero
cpu: 7
memory: 25Gi (limit) 100Mi (request)

Steps to reproduce the issue (command/config used to run Dgraph).

I am not sure what is causing the issue - just asking why this log is being spammed:

E0420 15:13:14.669162      20 log.go:32] Key: [0 0 14 116 101 108 101 109 101 116 114 121 46 110 97 109 101 2 10 105 99 97], Version : 52656231, meta: 2, userMeta: 4 valuePointer: {Fid:785 Len:2704 Offset:927509059}
E0420 15:13:14.669167      20 log.go:32] Key: [0 0 14 116 101 108 101 109 101 116 114 121 46 110 97 109 101 2 10 105 99 97], Version : 52656207, meta: 2, userMeta: 4 valuePointer: {Fid:785 Len:5188 Offset:927502381}
E0420 15:13:14.669172      20 log.go:32] Key: [0 0 14 116 101 108 101 109 101 116 114 121 46 110 97 109 101 2 10 105 99 97], Version : 52656203, meta: 2, userMeta: 4 valuePointer: {Fid:785 Len:1624 Offset:927500757}
....

As you can see from the timestamp its many times a second and fills my entire log in k8s. The system is processing extremely slowly and is pegging its 7c cpu. It is also being OOMkilled every few hours, here is the last 6h of memory for the one alpha: (each color is after a oomkill)Screen Shot 2021-04-20 at 11.15.53 AM
What causes that message to be printed? I could not find it in the dgraph code base (though there is not much to go on in the message)

1 Like
2

The message stopped spamming in the last while and memory usage returned to normal. What can cause that message? Seems like a badger struct just being printed out with %#v or something.

3

ah this seems to be a version of the problem Error: file with ID: X not found rearing its ugly head again. Just this time it was printing as fast as possible in blocks like:

E0420 21:29:01.775426      20 log.go:32] Unable to read: Key: [0 0 21 100 97 116 97 45 105 110 115 105 103 104 116 45 101 110 103 46 116 121 112 101 2 2 69 110 116 105 116 121], Version : 52719241, meta: 70, userMeta: 8 Error: file with ID: 791 not found
E0420 21:29:01.775491      20 log.go:32] Key: [0 0 21 100 97 116 97 45 105 110 115 105 103 104 116 45 101 110 103 46 116 121 112 101 2 2 69 110 116 105 116 121], Version : 52721774, meta: 64, userMeta: 4 valuePointer: {Fid:0 Len:0 Offset:0}
E0420 21:29:01.775502      20 log.go:32] Key: [0 0 21 100 97 116 97 45 105 110 115 105 103 104 116 45 101 110 103 46 116 121 112 101 2 2 69 110 116 105 116 121], Version : 52721607, meta: 64, userMeta: 4 valuePointer: {Fid:0 Len:0 Offset:0}

and I missed the first of the block.