# Schema Alter operation causing high query/mutation latencies **URL:** \ **Category:** Dgraph\ **Tags:** schema, status:accepted, ticket:created\ **Created:** [September 15, 2020, 5:11pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383 "2020-09-15T17:11:23Z")\ **Posts on this page:** 18\ **Page:** 1
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 15, 2020, 5:11pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/1 "2020-09-15T17:11:23Z")
We have an application where we need to perform regular schema alter operations to isolate some predicates for new datasets. This alter operation creates a new set of predicates. We have observed following behaviour whenever alter operation runs: 1. increase in pending queries: rate(dgraph\_pending\_queries\_total) 2. Spike in go routines 3. Spike in server latencies: dgraph\_latency\_bucket, dgraph\_grpc\_io\_server\_server\_latency\_bucket As per the [documentation](https://dgraph.io/docs/master/query-language/schema/#indexes-in-background) schema alter ops when run in background should not impact ongoing query/mutations. Cluster details: - 3 alpha, 3 zero pods - shard replica count: 3 - dgraph version: v20.07.0 - client version: [Release v20.03.1 · dgraph-io/dgraph4j · GitHub](https://github.com/dgraph-io/dgraph4j/releases/tag/v20.03.1) NOTE: Expecting pointers regarding alter op usage without compromising query/mutation performance ---
**Author:** ![chewxy](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/chewxy/32/4339_2.png) [@chewxy](https://discuss.dgraph.io/u/chewxy)\ **Post date:** [September 15, 2020, 7:14pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/2 "2020-09-15T19:14:29Z")
Hey @killerknv Welcome to the Dgraph community. We hope to see you around here more often. Now, when you say spike in goroutines, where are you seeing that? Goroutines are not like regular threads - you could spawn a million of them and they should have minimal impact on the running of the program if the program is structured well (i.e no communication deadlock bugs) More concerning is the spike in latencies. @ibrahim - ideas? ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 15, 2020, 8:08pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/3 "2020-09-15T20:08:22Z")
@chewxy Number of go routines (for dgraph alpha pods) are not really an issue, just an observation. Its just that it corresponds to latency increase in most cases ---
**Author:** ![ibrahim](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ibrahim/32/6387_2.png) [@ibrahim](https://discuss.dgraph.io/u/ibrahim)\ **Post date:** [September 16, 2020, 11:51am UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/4 "2020-09-16T11:51:05Z")
Hey @killerknv, the spike in goroutines is expected because of the re-indexing. Can you collect some traces from [https://dgraph.io/docs/deploy/tracing/#examining-traces-with-jaeger](https://dgraph.io/docs/deploy/tracing/#examining-traces-with-jaeger) while the alter operation is active? I’m looking for spans that are the slowest. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 16, 2020, 5:35pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/5 "2020-09-16T17:35:02Z")
@ibrahim While enabling the tracer on production might take some time, I wanted to have a better understanding on how schema updates work. Same schema updates take ~2 sec on a fresh dgraph cluster, where as it takes around 60s - 100s on a cluster that has considerable amount of data and receiving query/mutation requests. Considering the fact that schema updates have addition of new predicates, It should not impact operations on existing predicates and update time should not be increase by this much. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 16, 2020, 9:54pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/6 "2020-09-16T21:54:36Z")
@ibrahim I tried to reproduce the same behaviour on a test setup. alter op response time increased from 600ms to 5.24 s. Also observed increased latencies for ongoing query/mutations. jaeger trace for alter op ![Screenshot 2020-09-17 at 2.46.10 AM](https://canada1.discourse-cdn.com/flex007/uploads/dgraph/original/2X/4/47021c4dae30a6bae486a0ca9d749b7999016f41.png) trace for Server.mutate ![Screenshot 2020-09-17 at 3.23.51 AM](https://canada1.discourse-cdn.com/flex007/uploads/dgraph/original/2X/b/be4489f0706c48cbe8f413a71f156400049894fc.png) ---
**Author:** ![ibrahim](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ibrahim/32/6387_2.png) [@ibrahim](https://discuss.dgraph.io/u/ibrahim)\ **Post date:** [September 17, 2020, 7:23am UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/7 "2020-09-17T07:23:17Z")
> [@killerknv](#): > > Same schema updates take ~2 sec on a fresh dgraph cluster, where as it takes around 60s - 100s on a cluster that has considerable amount of data and receiving query/mutation requests. @ashishgoswami would have more information about this but I think we put mutations on hold while we’re indexing data. > [@killerknv](#): > > Considering the fact that schema updates have addition of new predicates, It should not impact operations on existing predicates and update time should not be increase by this much. New predicates could be associated with old nodes. In that case your query response would change and dgraph needs to handle that too. From the spans, it looks like a lot of time was spent waiting for the maxAssigned. @ashishgoswami is the delay expected? ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 21, 2020, 4:37pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/8 "2020-09-21T16:37:33Z")
@ashishgoswami @ibrahim any updates here ? We are also noticing very high dgraph grpc server latencies (dgraph\_grpc\_io\_server\_server\_latency\_bucket) after a peak in edge creation rate. ![Screenshot 2020-09-21 at 9.50.04 PM](https://canada1.discourse-cdn.com/flex007/uploads/dgraph/original/2X/6/6e724b546925f8138892d8f3a650f298c3c1c583.png) Sequence of events seems to be as following: Increase in number of mutations (edge creation rate) → consistent increase in pending queries → high server latencies We were able to recover completely from this only after rolling restart of the alpha nodes. ---
**Author:** ![ashishgoswami](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ashishgoswami/32/3416_2.png) [@ashishgoswami](https://discuss.dgraph.io/u/ashishgoswami)\ **Post date:** [September 23, 2020, 2:12pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/11 "2020-09-23T14:12:18Z")
Hi @killerknv, Thanks for raising the issue. Dgraph uses Raft protocol internally. It acts runs as a state machine. Hence at any point of time only one mutation is applied(however same mutation is broken into multiple parts and applied concurrently). This can be the reason for difference in time when alter is run on fresh cluster and alter is run on cluster with running mutations/queries. Although difference mentioned by you is very high(2s vs 60s). Even though predicates are new, we do some checks for them like cancelling in progress transactions for predicates etc. Can you share your benchmarks with us? We would like to reproduce this at our end. I am not very sure if the latency difference should be this big. Also I feel that increase in mutations/pending queries should be for sometime, but eventually everything should run normally. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 23, 2020, 2:50pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/12 "2020-09-23T14:50:17Z")
@ashishgoswami Let me know what all details you need regarding benchmark. The metrics shared are from our production cluster. Total number of predicates: 4882 Number of predicates per schema alter operation: 16 Most of our mutations span across 3-4 predicates. Pending queries, latencies recovered once we restarted the pods. This also looks like a problem with default helm charts, liveliness, readiness probes are disabled. They could have been useful if an alpha process gets stuck. Is there any recommended configuration for readiness, liveliness probe that we can use. Not sure of the story behind disabling these. ---
**Author:** ![ashishgoswami](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ashishgoswami/32/3416_2.png) [@ashishgoswami](https://discuss.dgraph.io/u/ashishgoswami)\ **Post date:** [September 24, 2020, 3:19am UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/13 "2020-09-24T03:19:23Z")
Hi @killerknv, Thanks for providing the above information. As you said, you are able to reproduce this on test setup, would it be possible to share your test scripts with us? You can share those by personal message. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 24, 2020, 12:35pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/14 "2020-09-24T12:35:16Z")
We had reproduced the issue on test deployment of a microservice responsible for generating mutations and alter ops. I will need to reproduce it using a simpler script which can be easily shared. @ashishgoswami Meanwhile is there a recommended configuration for readiness, liveliness probes that we can use. I could use [default values](https://github.com/dgraph-io/charts/blob/6734572badce7cf15c4333872043e6273cab88ca/charts/dgraph/values.yaml#L317) after enabling the probes. ---
**Author:** ![ashishgoswami](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ashishgoswami/32/3416_2.png) [@ashishgoswami](https://discuss.dgraph.io/u/ashishgoswami)\ **Post date:** [September 28, 2020, 8:55am UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/15 "2020-09-28T08:55:06Z")
Tagging @dmai for the 2nd part. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [September 28, 2020, 6:24pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/16 "2020-09-28T18:24:52Z")
@ashishgoswami I have shared the script to reproduce schema alter operations via message. Running the same set of schema alter ops even on a fresh cluster causes very high memory usage on alpha pods and eventually gets stuck in state where no more alter ops are possible. Memory profile for the same: ![alpha_anz2_heap](https://canada1.discourse-cdn.com/flex007/uploads/dgraph/original/2X/9/9bab0a4be0f3ae5331b8064d9bd6e1bc3e33deed.png) ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [October 8, 2020, 10:40pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/17 "2020-10-08T22:40:04Z")
@ashishgoswami Couldn’t reproduce the same on v1.2.7. Its looks like the issue is limited to v20.x.x ---
**Author:** ![anand](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/anand/32/5674_2.png) [@anand](https://discuss.dgraph.io/u/anand)\ **Post date:** [October 9, 2020, 2:19pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/21 "2020-10-09T14:19:34Z")
Hi Kesharee, Could you please also share the resources view (RAM, CPU) for each alpha and zero? There are a few switches that have been recently added that might help, and I would like to compare. ---
**Author:** ![killerknv](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/killerknv/32/4931_2.png) [@killerknv](https://discuss.dgraph.io/u/killerknv)\ **Post date:** [October 12, 2020, 5:44pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/22 "2020-10-12T17:44:20Z")
@anand Following is the cluster configuration: ```auto alpha pods: 12 * (14 G, 8 cpu) zero pods: 3 * (6G, 4 cpu) shard replica count: 3 ``` ---
**Author:** ![ibrahim](https://yyz1.discourse-cdn.com/flex007/user_avatar/discuss.dgraph.io/ibrahim/32/6387_2.png) [@ibrahim](https://discuss.dgraph.io/u/ibrahim)\ **Post date:** [October 13, 2020, 3:16pm UTC](https://discuss.dgraph.io/t/schema-alter-operation-causing-high-query-mutation-latencies/10383/23 "2020-10-13T15:16:39Z")
From the profile, it looks like there were too many memtables (the `newArena`). This will happen when a lot of badger instances are opened at the same time. Each re-indexing call opens a new badger DB and that’s why we’re seeing high memory usage. > [@killerknv](#): > > Couldn’t reproduce the same on v1.2.7. Its looks like the issue is limited to v20.x.x v1.2.7 should have the same issue since we do reindexing the same way in all the versions. > We’re starting too many builders in the background and that’s causing too many badger DB which leads to heavy memory usage. @killerknv I’ll accept this as a bug and we’ll try to resolve this soon.