Query too slow after adding float index

Issues Dgraph
, ,
1

Moved from GitHub dgraph/5606

Posted by coralzu:

What version of Dgraph are you using?

v20.0.03 v1.2.5

Have you tried reproducing the issue with the latest release?

yes

What is the hardware spec (RAM, OS)?

16GB RAM windows 10

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

1、start a new dgraph,add some float data

QQ图片20200609120500
QQ图片202006091205001920×326 11.2 KB

2、run a filter query,it Normal return

{   
  body(func:type(test)) @filter(le(zmj,"12222.08") and ge(zmj,"50")){
  count(uid)
	}    
}

QQ图片20200609121434
QQ图片202006091214341435×803 35.5 KB

3、Add float type index to predicate，run the query again
I got a timeout error , And dgraph uses a lot of memory

QQ图片20200609122037
QQ图片202006091220371452×539 27.5 KB

QQ图片20200609122119
QQ图片20200609122119833×207 12 KB

this is my alpha log ,It seem to got some error

I0609 14:41:45.892112   13324 log.go:34] Rebuilding index for predicate zmj (1/2): Created batch of size: 4.4 MB in 355.9971ms.
I0609 14:41:45.906112   13324 log.go:34] Rebuilding index for predicate zmj (1/2): Created batch of size: 166 kB in 13.0006ms.
I0609 14:41:45.906112   13324 log.go:34] Rebuilding index for predicate zmj (1/2): Sent 95001 keys
badger 2020/06/09 14:41:46 INFO: Rebuilding index for predicate zmj (2/2): Created batch of size: 1.6 MB in 95.0092ms.
badger 2020/06/09 14:41:46 INFO: Rebuilding index for predicate zmj (2/2): Sent 28718 keys
badger 2020/06/09 14:41:46 INFO: Got compaction priority: {level:0 score:1.73 dropPrefix:[]}
badger 2020/06/09 14:41:46 INFO: Running for level: 0
badger 2020/06/09 14:41:46 INFO: LOG Compact 0->1, del 1 tables, add 1 tables, took 50.0412ms
badger 2020/06/09 14:41:46 INFO: Compaction for level: 0 DONE
badger 2020/06/09 14:41:46 INFO: Force compaction on level 0 done
I0609 14:41:46.261148   13324 mutation.go:170] Done schema update predicate:"zmj" value_type:FLOAT directive:INDEX tokenizer:"float"
I0609 14:41:46.261148   13324 server.go:220] ALTER op: schema:"<zmj>: float @index(float) ."  done
I0609 14:42:31.344926   13324 groups.go:912] Zero leadership changed. Renewing oracle delta stream.
E0609 14:42:31.481926   13324 groups.go:888] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0609 14:42:31.653925   13324 groups.go:848] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0609 14:42:31.733925   13324 groups.go:857] Got Zero leader: localhost:5080
I0609 14:47:12.104160   13324 groups.go:912] Zero leadership changed. Renewing oracle delta stream.
E0609 14:47:12.561160   13324 groups.go:888] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0609 14:47:12.832162   13324 groups.go:848] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0609 14:47:13.257161   13324 groups.go:857] Got Zero leader: localhost:5080
I0609 14:47:13.847161   13324 groups.go:912] Zero leadership changed. Renewing oracle delta stream.
E0609 14:47:13.965161   13324 groups.go:888] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0609 14:47:14.824160   13324 groups.go:848] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0609 14:47:17.039242   13324 groups.go:857] Got Zero leader: localhost:5080
I0609 14:47:17.039242   13324 groups.go:912] Zero leadership changed. Renewing oracle delta stream.
E0609 14:47:17.044244   13324 groups.go:888] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0609 14:47:18.493242   13324 groups.go:848] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0609 14:47:18.730241   13324 groups.go:857] Got Zero leader: localhost:5080
I0609 14:47:22.541243   13324 groups.go:912] Zero leadership changed. Renewing oracle delta stream.
E0609 14:47:22.553242   13324 groups.go:888] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0609 14:47:22.832242   13324 groups.go:848] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0609 14:47:23.203242   13324 groups.go:857] Got Zero leader: localhost:5080
W0609 14:47:23.676243   13324 draft.go:1015] Raft.Ready took too long to process: Timer Total: 256ms. Breakdown: [{disk 139ms} {sync 81ms} {proposals 24ms} {advance 0s}] Num entries: 1. MustSync: true

Expected behaviour and actual result.

I think indexes should make queries faster. But when I use dgrpah in the actual project, the addition of float index makes my query slower, so I specifically did this test. I’m confused about why I got this.

2

Willem520 commented :

Hi, I am also an user of Dgraph.from my experience,when you write data, the badger will do some compaction. so the data what you care about maybe have been moved. so it cost much time to get it.

3

OmarAyo commented :

Hi @coralzu,

Quick question, does this query always take too much time to run, what about if you try a couple of time more ?

Would you provide us the dataset you are using in this test so we can reproduce ourself

Best,
Omar

4

coralzu commented :

Thank you for your reply. @OmarAyo
I’ve tried to execute the query later; tried to restart; tried to export, and then reloaded to the new dgraph using dgraph bulk loader. I always get the error. this is my dataset.

dgraph.r10003.u0611.0218.zip