Drop in throughput after sharding/grouping of alpha

What I want to do

想确认下分片后为什么吞吐量反而下降了。
I noticed after sharding, the throughput drops. Why?

What I did

压测方式:使用jmeter访问http端口。
Method: Use JMeter to monitor/query the HTTP port.

Dgraph Query URI:http://{vip}/dgraph-alpha-public/query
Query parameters:

{"query":"{ \nnodes(func:eq(identity_id, distinct_id_lyf_test4)) { \n   uid \n   identity_id \n   tenant_id \n   namespace \n   type \n   create_time \n   model_type \n   account_reverse : ~account_relation{ \n     namespace \n     identity_id \n     type \n     model_type \n     create_time \n     tenant_id \n     uid \n     relation{ \n         uid \n         namespace \n         identity_id \n         type \n         create_time \n         model_type \n         tenant_id \n        source{ \n             uid \n             source_id \n             source_type \n             create_time \n             primary \n             tenant_id \n             model_type \n         } \n     } \n   } \n   account_relation{ \n     namespace \n     identity_id \n     type \n     model_type \n     create_time \n     tenant_id \n     uid \n     relation{ \n         uid \n         namespace \n         identity_id \n         type \n         create_time \n         model_type \n         tenant_id \n        source{ \n             uid \n             source_id \n             source_type \n             create_time \n             primary \n             tenant_id \n             model_type \n         } \n     } \n   } \n   relation{ \n     uid \n     identity_id \n     tenant_id \n     namespace \n     type \n     create_time \n     model_type \n     source{ \n         uid \n         source_id \n         source_type \n         create_time \n         primary \n         tenant_id \n         model_type \n     } \n   } \n   reverse : ~relation{ \n     uid \n     identity_id \n     tenant_id \n     namespace \n     type \n     create_time \n     model_type \n     account_reverse : ~account_relation{ \n         namespace \n         identity_id \n         type \n         model_type \n         create_time \n         tenant_id \n         uid \n         relation{ \n             uid \n             namespace \n             identity_id \n             type \n             create_time \n             model_type \n             tenant_id \n                source{ \n                     uid \n                     source_id \n                     source_type \n                     create_time \n                     primary \n                     tenant_id \n                     model_type \n                 } \n         } \n     } \n     account_relation{ \n         namespace \n         identity_id \n         type \n         model_type \n         create_time \n         tenant_id \n         uid \n         relation{ \n             uid \n             namespace \n             identity_id \n             type \n             create_time \n             model_type \n             tenant_id \n                source{ \n                     uid \n                     source_id \n                     source_type \n                     create_time \n                     primary \n                     tenant_id \n                     model_type \n                 } \n         } \n     } \n     relation{ \n         uid \n         identity_id \n         tenant_id \n         namespace \n         type \n         create_time\n         model_type \n         source{ \n             uid \n             source_id \n             source_type \n             create_time \n             primary \n             tenant_id \n             model_type \n         } \n     } \n  } \n} \n}","variables":{}}

Mutation URI:http://{vip}/dgraph-alpha-public/mutation
Mutation parameters:

{
  set{
_:kYEqZY085a <type> "aff_id" .
_:kYEqZY085a <namespace> "cdp" .
_:kYEqZY085a <identity_id> "1505814931620393" .
_:kYEqZY085a <create_time> "2021-02-22T15:33:09.412" .
_:kYEqZY085a <tenant_id> "lyf_test" .
_:kYEqZY085a <dgraph.type> "Identity" .
_:kYEqZYzkli <type> "phone" .
_:kYEqZYzkli <namespace> "phone" .
_:kYEqZYzkli <identity_id> "13366246858_1" .
_:kYEqZYzkli <create_time> "2021-02-09T12:54:55.026" .
_:kYEqZYzkli <tenant_id> "lyf_test" .
_:kYEqZYzkli <dgraph.type> "Identity" .
_:kYEqZY085a <relation> _:kYEqZYzkli .
_:kYEqZYQVtm <source_type> "AFF_CRM" .
_:kYEqZYQVtm <source_id> "-1" .
_:kYEqZYQVtm <create_time> "2021-02-09T12:54:55.026" .
_:kYEqZYQVtm <tenant_id> "lyf_test" .
_:kYEqZYQVtm <primary> "false" .
_:kYEqZYQVtm <dgraph.type> "Source" .
_:kYEqZYzkli <source> _:kYEqZYQVtm .
  }
}

{vip}是访问k8s ServiceName的vip机器。
{vip] is the k8s ServiceName query machine.

部署配置:
三个zero,三个alpha,均是默认启动参数:
查询最大吞吐量:5000并发查询循环3次,最大吞吐量3587。
突变最大吞吐量:1000并发突变循环3次,最大吞吐量1642。

三个zero,五个alpha,均是默认启动参数:
重新均衡谓词后的结果:

Deployment configuration:
Three zeros and three alphas with the default startup parameters:
Maximum query throughput: 5000 concurrent query loops 3 times, with a maximum throughput of 3587.
Maximum throughput of mutation: 1000 concurrent mutation cycles for 3 times, maximum throughput of 1642.

Three zeros and five alphas with the default startup parameters:
The result after rebalancing the predicate:

查询最大吞吐量:5000并发查询循环3次,最大吞吐量358。
突变最大吞吐量:1000并发突变循环3次,最大吞吐量1447。
吞吐量下降的很明显。

Maximum query throughput: 5000 concurrent query loops 3 times, and the maximum throughput is 358.
Maximum throughput of mutation: 1000 concurrent mutation cycles for 3 times, and the maximum throughput is 1447.
The throughput has dropped significantly.

指标数据:
已有的内存、cpu和go_goroutines、dgraph_alpha_health_status等指标数据均正常。其中alphadgraph_pending_proposals_total指标只有alpha-4达到上限256,而其他节点没有明显上涨。将该指标调整至1024后,使用jmeter模拟3000并发请求90秒,发现只有alpha-4的pending proposals达到上限1024,且cpu使用率很高,出现处理异常和事务停止异常。而其他的alpha却是低cpu使用率。

Other metrics:
All other internal metrics (CPU, goroutines, dgraph_alpha_health_status, etc) are normal. The alphadgraph_pending_proposals_total metric is a little odd: Only alph-4 is hitting the limit of 256, while other nodes have not risen significantly.

After adjusting the index to 1024, using jmeter to simulate 3000 concurrent requests for 90 seconds, we found that only the pending proposals of alpha-4 reached the upper limit of 1024, and the CPU usage rate was high, processing exceptions and transaction stop exceptions occurred. The other alphas are low cpu usage.

异常信息:

{"errors":[{"message":"Server overloaded with pending proposals. Please retry later","extensions":{"code":"ErrorInvalidRequest"}}],"data":null}
{"errors":[{"message":"rpc error: code = Aborted desc = Transaction has been aborted. Please retry","extensions":{"code":"ErrorInvalidRequest"}}],"data":null}

Dgraph metadata

部署环境:k8s
alpha pod配置:

Limits:
    cpu: 12
    memory: 32Gi
Requests:
    cpu: 8
    memory: 16Gi

zero pod配置:

    Limits:
      cpu:     4
      memory:  8Gi
    Requests:
      cpu:      2
      memory:   8G

schema:

<account_relation>: [uid] @reverse .
<create_time>: default .
<dgraph.cors>: [string] @index(exact) @upsert .
<dgraph.drop.op>: string .
<dgraph.graphql.p_query>: string .
<dgraph.graphql.p_sha256hash>: string @index(exact) .
<dgraph.graphql.schema>: string .
<dgraph.graphql.schema_created_at>: datetime .
<dgraph.graphql.schema_history>: string .
<dgraph.graphql.xid>: string @index(exact) @upsert .
<identity_id>: string @index(hash) .
<model_type>: int @index(int) .
<namespace>: string @index(hash) .
<primary>: bool @index(bool) .
<relation>: [uid] @reverse .
<source>: [uid] @reverse .
<source_id>: string @index(hash) .
<source_type>: default .
<tenant_id>: string @index(hash) .
<type>: string @index(hash) .
type <AccountIdentity> {
	account_relation
	create_time
	identity_id
	model_type
	namespace
	relation
	source
	tenant_id
	type
}
type <Identity> {
	create_time
	identity_id
	namespace
	relation
	source
	tenant_id
	type
}
type <Source> {
	source_type
	source_id
	primary
	create_time
	tenant_id
}
type <dgraph.graphql> {
	dgraph.graphql.schema
	dgraph.graphql.xid
}
type <dgraph.graphql.history> {
	dgraph.graphql.schema_history
	dgraph.graphql.schema_created_at
}
type <dgraph.graphql.persisted_query> {
	dgraph.graphql.p_query
	dgraph.graphql.p_sha256hash
}
type <dgraph.type.cors> {
	dgraph.cors
}
dgraph version
Dgraph version   : v20.11.2
Dgraph codename  : tchalla-2
Commit timestamp : 2021-02-23 13:07:17 +0530
Branch           : HEAD
Go version       : go1.15.5
jemalloc enabled : true

当前集群状态信息:
Current status

{"counter":"1031133","groups":{"1":{"members":{"2":{"id":"2","groupId":1,"addr":"dgraph-alpha-1.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"1619678374","clusterInfoOnly":false,"forceGroupId":false},"6":{"id":"6","groupId":1,"addr":"dgraph-alpha-2.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":true,"amDead":false,"lastUpdate":"1619763968","clusterInfoOnly":false,"forceGroupId":false},"7":{"id":"7","groupId":1,"addr":"dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"1619763911","clusterInfoOnly":false,"forceGroupId":false}},"tablets":{"account_relation":{"groupId":1,"predicate":"account_relation","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"create_time":{"groupId":1,"predicate":"create_time","force":false,"onDiskBytes":"250372977","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"1056268508"},"dgraph.cors":{"groupId":1,"predicate":"dgraph.cors","force":false,"onDiskBytes":"199","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"75"},"dgraph.drop.op":{"groupId":1,"predicate":"dgraph.drop.op","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.p_query":{"groupId":1,"predicate":"dgraph.graphql.p_query","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.p_sha256hash":{"groupId":1,"predicate":"dgraph.graphql.p_sha256hash","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.schema":{"groupId":1,"predicate":"dgraph.graphql.schema","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.schema_created_at":{"groupId":1,"predicate":"dgraph.graphql.schema_created_at","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.schema_history":{"groupId":1,"predicate":"dgraph.graphql.schema_history","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.graphql.xid":{"groupId":1,"predicate":"dgraph.graphql.xid","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"dgraph.type":{"groupId":1,"predicate":"dgraph.type","force":false,"onDiskBytes":"316320365","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"987516220"},"model_type":{"groupId":1,"predicate":"model_type","force":false,"onDiskBytes":"0","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"0"},"namespace":{"groupId":1,"predicate":"namespace","force":false,"onDiskBytes":"176700607","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"637472108"},"relation":{"groupId":1,"predicate":"relation","force":false,"onDiskBytes":"196587853","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"437145360"},"source":{"groupId":1,"predicate":"source","force":false,"onDiskBytes":"203302443","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"455500437"},"tenant_id":{"groupId":1,"predicate":"tenant_id","force":false,"onDiskBytes":"359673272","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"981317713"}},"snapshotTs":"2561814","checksum":"3340003164330354535","checkpointTs":"0"},"2":{"members":{"8":{"id":"8","groupId":2,"addr":"dgraph-alpha-3.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":true,"amDead":false,"lastUpdate":"1619763902","clusterInfoOnly":false,"forceGroupId":false},"9":{"id":"9","groupId":2,"addr":"dgraph-alpha-4.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false}},"tablets":{"identity_id":{"groupId":2,"predicate":"identity_id","force":false,"onDiskBytes":"744577361","remove":false,"readOnly":false,"moveTs":"1552836","uncompressedBytes":"1274366935"},"primary":{"groupId":2,"predicate":"primary","force":false,"onDiskBytes":"73127349","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"354713747"},"source_id":{"groupId":2,"predicate":"source_id","force":false,"onDiskBytes":"368934064","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"827124029"},"source_type":{"groupId":2,"predicate":"source_type","force":false,"onDiskBytes":"63111162","remove":false,"readOnly":false,"moveTs":"2561815","uncompressedBytes":"245374047"},"type":{"groupId":2,"predicate":"type","force":false,"onDiskBytes":"197447263","remove":false,"readOnly":false,"moveTs":"0","uncompressedBytes":"910255979"}},"snapshotTs":"2561814","checksum":"13039052466481007906","checkpointTs":"0"}},"zeros":{"2":{"id":"2","groupId":0,"addr":"dgraph-zero-1.dgraph-zero.crm-test.svc.cluster.local:5080","leader":true,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false},"3":{"id":"3","groupId":0,"addr":"dgraph-zero-2.dgraph-zero.crm-test.svc.cluster.local:5080","leader":false,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false},"4":{"id":"4","groupId":0,"addr":"dgraph-zero-0.dgraph-zero.crm-test.svc.cluster.local:5080","leader":false,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false}},"maxLeaseId":"17900000","maxTxnTs":"2570000","maxRaftId":"9","removed":[{"id":"3","groupId":1,"addr":"dgraph-alpha-2.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"1615991006","clusterInfoOnly":false,"forceGroupId":false},{"id":"4","groupId":1,"addr":"dgraph-alpha-2.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false},{"id":"5","groupId":1,"addr":"dgraph-alpha-2.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false},{"id":"1","groupId":0,"addr":"dgraph-zero-0.dgraph-zero.crm-test.svc.cluster.local:5080","leader":true,"amDead":false,"lastUpdate":"0","clusterInfoOnly":false,"forceGroupId":false},{"id":"1","groupId":1,"addr":"dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080","leader":false,"amDead":false,"lastUpdate":"1615990975","clusterInfoOnly":false,"forceGroupId":false}],"cid":"fec6a030-0c07-4fe9-a775-219482e41177","license":{"user":"","maxNodes":"18446744073709551615","expiryTs":"1617290026","enabled":false}}
1 Like

I will post a translation in a bit then I will investigate this issue.
我将会把以上的帖子翻译。。。 要先吃早餐, 然后我就查一查

After I turned on the logRequest switch, I found that the number of requests sent to each alpha pod was the same, but only alpha-4 processing had high pending proposals and high CPU usage.
我将logRequest开关打开后,发现发送到每个alpha pod的请求数量都是一致的,但是只有alpha-4处理出现很高的pending proposals,且CPU占用率高。

This is the time-consuming trace information for querying and mutation on alpha-4. Please help us to find out the reason for the high time-consuming.
这是alpha-4上查询和突变耗时较高的trace信息,麻烦帮看下耗时高的原因。
@chewxy

query:

2021/05/08-11:59:35.026091      . 14975 trace_id: ee7690bfb65c5ab8ccb14a565d8e6e51 span_id: e651dd669d4ff6b9 parent_span_id: a588d3a37120ef3c
           11:59:35.036978      . 10887 Zero uids for "tenant_id"
           11:59:35.036986      .     7 End. Took 2.866µs  Attributes:{funcId=211046472, funcName="query.ProcessGraph.uid"}
           11:59:35.036991      .     5 Start.  Attributes:{funcId=1999480660, funcName="query.ProcessGraph.source"}
           11:59:35.037009      .    17 ProcessTaskOverNetwork. attr: source gid: 1, readTs: 2677287, node id: 9
           11:59:35.037012      .     2 End. Took 4.196µs  Attributes:{funcId=690810992, funcName="query.ProcessGraph.uid"}
           11:59:35.037012      .     0 ProcessTaskOverNetwork. attr: model_type gid: 1, readTs: 2677287, node id: 9
           11:59:35.037027      .    14 ProcessTaskOverNetwork. attr: namespace gid: 1, readTs: 2677287, node id: 9
           11:59:35.037029      .     2 Start.  Attributes:{funcId=791516443, funcName="query.ProcessGraph.namespace"}
           11:59:35.037037      .     7 Start.  Attributes:{funcId=806715483, funcName="query.ProcessGraph.create_time"}
           11:59:35.037052      .    15 Start.  Attributes:{funcId=645827068, funcName="query.ProcessGraph.type"}
           11:59:35.037139      .    87 End. Took 847ns  Attributes:{funcId=1677858280, funcName="expandSubgraph: tenant_id"}
           11:59:35.037179      .    40 End. Took 4.974352ms  Attributes:{funcId=840045504, funcName="query.ProcessGraph.relation"}
           11:59:35.037185      .     6 Zero uids for "~account_relation"
           11:59:35.037201      .    15 End. Took 883ns  Attributes:{funcId=1758182794, funcName="expandSubgraph: tenant_id"}
           11:59:35.037208      .     6 Zero uids for "create_time"
           11:59:35.037219      .    11 Reply from server. len: 2 gid: 1 Attr: source
           11:59:35.037222      .     2 Start.  Attributes:{funcId=267176399, funcName="expandSubgraph: model_type"}
           11:59:35.037226      .     3 Zero uids for "identity_id"
           11:59:35.037231      .     5 End. Took 171.391µs  Attributes:{funcId=683466212, funcName="query.ProcessGraph.identity_id"}
           11:59:35.037232      .     1 End. Took 946.965µs  Attributes:{funcId=1213106277, funcName="query.ProcessGraph.create_time"}
           11:59:35.037244      .    12 Start.  Attributes:{funcId=306402900, funcName="expandSubgraph: type"}
           11:59:35.037277      .    32 Zero uids for "tenant_id"
           11:59:35.037284      .     6 End. Took 1.663023ms  Attributes:{funcId=1218283187, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.037290      .     5 Zero uids for "source"
           11:59:35.037294      .     4 End. Took 3.387929ms  Attributes:{funcId=1710215804, funcName="query.ProcessGraph.source"}
           11:59:35.037415      .   121 Start.  Attributes:{funcId=431434827, funcName="expandSubgraph: identity_id"}
           11:59:35.037419      .     3 End. Took 665ns  Attributes:{funcId=431434827, funcName="expandSubgraph: identity_id"}
           11:59:35.037426      .     6 Zero uids for "tenant_id"
           11:59:35.037428      .     2 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.037435      .     6 Zero uids for "identity_id"
           11:59:35.037440      .     5 End. Took 2.53468ms  Attributes:{funcId=520065034, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.037442      .     1 End. Took 423.672µs  Attributes:{funcId=1353265591, funcName="query.ProcessGraph.identity_id"}
           11:59:35.037456      .    14 End. Took 2.400351ms  Attributes:{funcId=1351391578, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.037485      .    28 ProcessTaskOverNetwork. attr: namespace gid: 1, readTs: 2677287, node id: 9
           11:59:35.037506      .    20 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.037536      .    30 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.037552      .    15 ProcessTaskOverNetwork. attr: create_time gid: 1, readTs: 2677287, node id: 9
           11:59:35.037585      .    33 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.037629      .    43 ProcessTaskOverNetwork. attr: type gid: 2, readTs: 2677287, node id: 9
           11:59:35.037737      .   108 Start.  Attributes:{funcId=7799827, funcName="expandSubgraph: type"}
           11:59:35.037740      .     3 End. Took 505ns  Attributes:{funcId=7799827, funcName="expandSubgraph: type"}
           11:59:35.037742      .     1 End. Took 7.417468ms  Attributes:{funcId=1122556161, funcName="query.ProcessGraph.account_reverse.~account_relation"}
           11:59:35.037744      .     2 Zero uids for "type"
           11:59:35.037748      .     3 End. Took 123.322µs  Attributes:{funcId=645827068, funcName="query.ProcessGraph.type"}
           11:59:35.037761      .    13 ProcessTaskOverNetwork. attr: source gid: 1, readTs: 2677287, node id: 9
           11:59:35.037785      .    23 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.037834      .    49 Start.  Attributes:{funcId=1928513899, funcName="expandSubgraph: source"}
           11:59:35.037841      .     6 End. Took 2.55µs  Attributes:{funcId=1928513899, funcName="expandSubgraph: source"}
           11:59:35.037861      .    20 Reply from server. len: 0 gid: 1 Attr: tenant_id
           11:59:35.037866      .     5 Start.  Attributes:{funcId=606083944, funcName="expandSubgraph: tenant_id"}
           11:59:35.037869      .     2 End. Took 470ns  Attributes:{funcId=606083944, funcName="expandSubgraph: tenant_id"}
           11:59:35.037888      .    18 Reply from server. len: 0 gid: 1 Attr: tenant_id
           11:59:35.037901      .    13 End. Took 1.849µs  Attributes:{funcId=267176399, funcName="expandSubgraph: model_type"}
           11:59:35.037905      .     3 Start.  Attributes:{funcId=1896062999, funcName="expandSubgraph: tenant_id"}
           11:59:35.037919      .    14 Zero uids for "tenant_id"
           11:59:35.037923      .     3 End. Took 810.582µs  Attributes:{funcId=296879333, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.037929      .     6 Start.  Attributes:{funcId=1063707246, funcName="query.ProcessGraph.model_type"}
           11:59:35.037930      .     0 End. Took 979ns  Attributes:{funcId=1896062999, funcName="expandSubgraph: tenant_id"}
           11:59:35.037932      .     1 Start.  Attributes:{funcId=1582365334, funcName="query.ProcessGraph.source_id"}
           11:59:35.037932      .     0 Start.  Attributes:{funcId=2000331983, funcName="query.ProcessGraph.uid"}
           11:59:35.037936      .     3 ProcessTaskOverNetwork. attr: model_type gid: 1, readTs: 2677287, node id: 9
           11:59:35.037940      .     4 ProcessTaskOverNetwork. attr: source_id gid: 2, readTs: 2677287, node id: 9
           11:59:35.037941      .     1 Reply from server. len: 0 gid: 1 Attr: model_type
           11:59:35.037949      .     7 End. Took 6.215µs  Attributes:{funcId=2000331983, funcName="query.ProcessGraph.uid"}
           11:59:35.037951      .     2 Start.  Attributes:{funcId=1327135661, funcName="expandSubgraph: model_type"}
           11:59:35.037955      .     4 Zero uids for "model_type"
           11:59:35.037960      .     5 End. Took 704ns  Attributes:{funcId=1327135661, funcName="expandSubgraph: model_type"}
           11:59:35.037968      .     7 Start.  Attributes:{funcId=25214830, funcName="query.ProcessGraph.create_time"}
           11:59:35.037976      .     7 Start.  Attributes:{funcId=1426746794, funcName="query.ProcessGraph.source_type"}
           11:59:35.037978      .     2 Zero uids for "tenant_id"
           11:59:35.037979      .     1 Reply from server. len: 0 gid: 1 Attr: create_time
           11:59:35.037984      .     4 Start.  Attributes:{funcId=738079504, funcName="query.ProcessGraph.primary"}
           11:59:35.037986      .     2 Start.  Attributes:{funcId=1548956256, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.037992      .     5 ProcessTaskOverNetwork. attr: create_time gid: 1, readTs: 2677287, node id: 9
           11:59:35.037994      .     1 Zero uids for "model_type"
           11:59:35.037999      .     5 ProcessTaskOverNetwork. attr: source_type gid: 2, readTs: 2677287, node id: 9
           11:59:35.038002      .     2 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038015      .    12 End. Took 958.797µs  Attributes:{funcId=1881454300, funcName="query.ProcessGraph.model_type"}
           11:59:35.038022      .     7 End. Took 976.204µs  Attributes:{funcId=73353201, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.038037      .    15 invokeNetworkRequest: Sending request to dgraph-alpha-1.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038058      .    21 End. Took 1.078µs  Attributes:{funcId=306402900, funcName="expandSubgraph: type"}
           11:59:35.038065      .     7 Zero uids for "type"
           11:59:35.038071      .     5 End. Took 980.011µs  Attributes:{funcId=2017543455, funcName="query.ProcessGraph.type"}
           11:59:35.038092      .    20 ProcessTaskOverNetwork. attr: primary gid: 2, readTs: 2677287, node id: 9
           11:59:35.038170      .    78 ProcessTaskOverNetwork. attr: tenant_id gid: 1, readTs: 2677287, node id: 9
           11:59:35.038179      .     8 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038194      .    15 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038214      .    19 Start.  Attributes:{funcId=1524756765, funcName="expandSubgraph: create_time"}
           11:59:35.038219      .     5 End. Took 846ns  Attributes:{funcId=1524756765, funcName="expandSubgraph: create_time"}
           11:59:35.038232      .    12 Reply from server. len: 0 gid: 1 Attr: namespace
           11:59:35.038238      .     6 Start.  Attributes:{funcId=625844365, funcName="expandSubgraph: namespace"}
           11:59:35.038241      .     2 End. Took 482ns  Attributes:{funcId=625844365, funcName="expandSubgraph: namespace"}
           11:59:35.038252      .    11 Zero uids for "create_time"
           11:59:35.038257      .     4 End. Took 1.214658ms  Attributes:{funcId=139948933, funcName="query.ProcessGraph.create_time"}
           11:59:35.038265      .     8 Zero uids for "namespace"
           11:59:35.038277      .    11 End. Took 796.426µs  Attributes:{funcId=791516443, funcName="query.ProcessGraph.namespace"}
           11:59:35.038286      .     8 End. Took 2.846571ms  Attributes:{funcId=1695848055, funcName="query.ProcessGraph.model_type"}
           11:59:35.038291      .     5 Zero uids for "relation"
           11:59:35.038295      .     3 End. Took 6.12428ms  Attributes:{funcId=1371299470, funcName="query.ProcessGraph.relation"}
           11:59:35.038299      .     4 Zero uids for "account_relation"
           11:59:35.038304      .     4 End. Took 7.858793ms  Attributes:{funcId=1065692898, funcName="query.ProcessGraph.account_relation"}
           11:59:35.038337      .    33 Reply from server. len: 0 gid: 1 Attr: create_time
           11:59:35.038340      .     3 Start.  Attributes:{funcId=525535854, funcName="expandSubgraph: source_id"}
           11:59:35.038345      .     4 End. Took 1.017µs  Attributes:{funcId=525535854, funcName="expandSubgraph: source_id"}
           11:59:35.038352      .     7 Start.  Attributes:{funcId=204544033, funcName="expandSubgraph: create_time"}
           11:59:35.038356      .     3 End. Took 762ns  Attributes:{funcId=204544033, funcName="expandSubgraph: create_time"}
           11:59:35.038365      .     8 Zero uids for "source_id"
           11:59:35.038367      .     2 Reply from server. len: 0 gid: 1 Attr: namespace
           11:59:35.038367      .     0 Start.  Attributes:{funcId=754213896, funcName="expandSubgraph: primary"}
           11:59:35.038370      .     3 End. Took 516ns  Attributes:{funcId=754213896, funcName="expandSubgraph: primary"}
           11:59:35.038376      .     5 Start.  Attributes:{funcId=1818051662, funcName="expandSubgraph: namespace"}
           11:59:35.038387      .    11 Zero uids for "primary"
           11:59:35.038392      .     4 End. Took 304.719µs  Attributes:{funcId=738079504, funcName="query.ProcessGraph.primary"}
           11:59:35.038397      .     5 End. Took 461.527µs  Attributes:{funcId=1582365334, funcName="query.ProcessGraph.source_id"}
           11:59:35.038407      .     9 Reply from server. len: 0 gid: 1 Attr: model_type
           11:59:35.038413      .     5 End. Took 1.039µs  Attributes:{funcId=1818051662, funcName="expandSubgraph: namespace"}
           11:59:35.038417      .     4 Zero uids for "create_time"
           11:59:35.038422      .     4 End. Took 877.16µs  Attributes:{funcId=806715483, funcName="query.ProcessGraph.create_time"}
           11:59:35.038429      .     6 Start.  Attributes:{funcId=986812733, funcName="expandSubgraph: model_type"}
           11:59:35.038433      .     3 End. Took 746ns  Attributes:{funcId=986812733, funcName="expandSubgraph: model_type"}
           11:59:35.038437      .     3 Reply from server. len: 0 gid: 1 Attr: source
           11:59:35.038446      .     9 Start.  Attributes:{funcId=1985948220, funcName="expandSubgraph: source"}
           11:59:35.038452      .     5 End. Took 2.34µs  Attributes:{funcId=1985948220, funcName="expandSubgraph: source"}
           11:59:35.038454      .     2 Zero uids for "namespace"
           11:59:35.038460      .     5 Zero uids for "model_type"
           11:59:35.038460      .     0 End. Took 1.439248ms  Attributes:{funcId=976477246, funcName="query.ProcessGraph.namespace"}
           11:59:35.038464      .     4 End. Took 1.454913ms  Attributes:{funcId=634555729, funcName="query.ProcessGraph.model_type"}
           11:59:35.038513      .    48 Start.  Attributes:{funcId=1283844312, funcName="query.ProcessGraph.uid"}
           11:59:35.038518      .     5 Start.  Attributes:{funcId=1315185316, funcName="query.ProcessGraph.source_id"}
           11:59:35.038520      .     1 End. Took 3.153µs  Attributes:{funcId=1283844312, funcName="query.ProcessGraph.uid"}
           11:59:35.038524      .     3 ProcessTaskOverNetwork. attr: source_id gid: 2, readTs: 2677287, node id: 9
           11:59:35.038530      .     6 Start.  Attributes:{funcId=784769467, funcName="query.ProcessGraph.source_type"}
           11:59:35.038531      .     0 Start.  Attributes:{funcId=926499285, funcName="query.ProcessGraph.create_time"}
           11:59:35.038543      .    12 Start.  Attributes:{funcId=677689213, funcName="query.ProcessGraph.model_type"}
           11:59:35.038544      .     0 ProcessTaskOverNetwork. attr: source_type gid: 2, readTs: 2677287, node id: 9
           11:59:35.038548      .     4 ProcessTaskOverNetwork. attr: create_time gid: 1, readTs: 2677287, node id: 9
           11:59:35.038553      .     4 Start.  Attributes:{funcId=10356715, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.038557      .     4 Start.  Attributes:{funcId=357743784, funcName="query.ProcessGraph.primary"}
           11:59:35.038559      .     1 ProcessTaskOverNetwork. attr: tenant_id gid: 1, readTs: 2677287, node id: 9
           11:59:35.038559      .     0 ProcessTaskOverNetwork. attr: model_type gid: 1, readTs: 2677287, node id: 9
           11:59:35.038566      .     6 ProcessTaskOverNetwork. attr: primary gid: 2, readTs: 2677287, node id: 9
           11:59:35.038567      .     1 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038591      .    23 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038604      .    13 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.038671      .    66 Start.  Attributes:{funcId=1301079536, funcName="expandSubgraph: source_id"}
           11:59:35.038674      .     3 End. Took 811ns  Attributes:{funcId=1301079536, funcName="expandSubgraph: source_id"}
           11:59:35.038678      .     3 Zero uids for "source_id"
           11:59:35.038682      .     4 End. Took 161.352µs  Attributes:{funcId=1315185316, funcName="query.ProcessGraph.source_id"}
           11:59:35.038685      .     3 Start.  Attributes:{funcId=206486813, funcName="expandSubgraph: primary"}
           11:59:35.038688      .     2 End. Took 485ns  Attributes:{funcId=206486813, funcName="expandSubgraph: primary"}
           11:59:35.038693      .     4 Zero uids for "primary"
           11:59:35.038697      .     4 End. Took 133.554µs  Attributes:{funcId=357743784, funcName="query.ProcessGraph.primary"}
           11:59:35.038718      .    21 Start.  Attributes:{funcId=1024208863, funcName="expandSubgraph: source_type"}
           11:59:35.038723      .     4 End. Took 1.376µs  Attributes:{funcId=1024208863, funcName="expandSubgraph: source_type"}
           11:59:35.038729      .     6 Zero uids for "source_type"
           11:59:35.038735      .     5 End. Took 195.443µs  Attributes:{funcId=784769467, funcName="query.ProcessGraph.source_type"}
           11:59:35.038855      .   119 Start.  Attributes:{funcId=1266552833, funcName="expandSubgraph: source_type"}
           11:59:35.038858      .     3 End. Took 676ns  Attributes:{funcId=1266552833, funcName="expandSubgraph: source_type"}
           11:59:35.038862      .     4 Zero uids for "source_type"
           11:59:35.038868      .     5 End. Took 872.316µs  Attributes:{funcId=1426746794, funcName="query.ProcessGraph.source_type"}
           11:59:35.038947      .    78 Reply from server. len: 1 gid: 1 Attr: create_time
           11:59:35.038956      .     9 Start.  Attributes:{funcId=348888000, funcName="expandSubgraph: create_time"}
           11:59:35.038959      .     2 End. Took 736ns  Attributes:{funcId=348888000, funcName="expandSubgraph: create_time"}
           11:59:35.038996      .    36 Zero uids for "create_time"
           11:59:35.039002      .     5 End. Took 1.013046ms  Attributes:{funcId=25214830, funcName="query.ProcessGraph.create_time"}
           11:59:35.039200      .   198 Reply from server. len: 1 gid: 1 Attr: tenant_id
           11:59:35.039209      .     9 Start.  Attributes:{funcId=1374601729, funcName="expandSubgraph: tenant_id"}
           11:59:35.039212      .     2 End. Took 780ns  Attributes:{funcId=1374601729, funcName="expandSubgraph: tenant_id"}
           11:59:35.039240      .    28 Zero uids for "tenant_id"
           11:59:35.039243      .     2 Reply from server. len: 1 gid: 1 Attr: model_type
           11:59:35.039246      .     2 End. Took 1.079802ms  Attributes:{funcId=1548956256, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.039259      .    13 Start.  Attributes:{funcId=907947494, funcName="expandSubgraph: model_type"}
           11:59:35.039263      .     4 End. Took 1.185µs  Attributes:{funcId=907947494, funcName="expandSubgraph: model_type"}
           11:59:35.039273      .     9 Reply from server. len: 0 gid: 1 Attr: source
           11:59:35.039278      .     5 Reply from server. len: 0 gid: 1 Attr: create_time
           11:59:35.039284      .     5 Start.  Attributes:{funcId=1083252449, funcName="expandSubgraph: source"}
           11:59:35.039285      .     0 Start.  Attributes:{funcId=434874481, funcName="expandSubgraph: create_time"}
           11:59:35.039289      .     4 End. Took 1.659µs  Attributes:{funcId=1083252449, funcName="expandSubgraph: source"}
           11:59:35.039293      .     4 End. Took 544ns  Attributes:{funcId=434874481, funcName="expandSubgraph: create_time"}
           11:59:35.039306      .    12 Zero uids for "model_type"
           11:59:35.039310      .     4 End. Took 1.378223ms  Attributes:{funcId=1063707246, funcName="query.ProcessGraph.model_type"}
           11:59:35.039312      .     2 Reply from server. len: 0 gid: 1 Attr: model_type
           11:59:35.039318      .     5 End. Took 3.773178ms  Attributes:{funcId=877981913, funcName="query.ProcessGraph.source"}
           11:59:35.039325      .     7 End. Took 6.846972ms  Attributes:{funcId=1106224419, funcName="query.ProcessGraph.relation"}
           11:59:35.039336      .    10 Start.  Attributes:{funcId=776966585, funcName="expandSubgraph: model_type"}
           11:59:35.039339      .     2 End. Took 493ns  Attributes:{funcId=776966585, funcName="expandSubgraph: model_type"}
           11:59:35.039342      .     2 Zero uids for "create_time"
           11:59:35.039347      .     4 End. Took 801.66µs  Attributes:{funcId=926499285, funcName="query.ProcessGraph.create_time"}
           11:59:35.039359      .    12 Start.  Attributes:{funcId=1690233459, funcName="query.ProcessGraph.model_type"}
           11:59:35.039365      .     5 Zero uids for "model_type"
           11:59:35.039367      .     1 Start.  Attributes:{funcId=2124252579, funcName="query.ProcessGraph.source_type"}
           11:59:35.039368      .     1 Start.  Attributes:{funcId=1575411271, funcName="query.ProcessGraph.primary"}
           11:59:35.039369      .     0 End. Took 811.614µs  Attributes:{funcId=677689213, funcName="query.ProcessGraph.model_type"}
           11:59:35.039373      .     4 Start.  Attributes:{funcId=202025286, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.039374      .     0 Start.  Attributes:{funcId=515637624, funcName="query.ProcessGraph.create_time"}
           11:59:35.039376      .     1 ProcessTaskOverNetwork. attr: source_type gid: 2, readTs: 2677287, node id: 9
           11:59:35.039380      .     4 Reply from server. len: 0 gid: 1 Attr: tenant_id
           11:59:35.039380      .     0 ProcessTaskOverNetwork. attr: tenant_id gid: 1, readTs: 2677287, node id: 9
           11:59:35.039383      .     2 ProcessTaskOverNetwork. attr: model_type gid: 1, readTs: 2677287, node id: 9
           11:59:35.039391      .     8 Start.  Attributes:{funcId=528783934, funcName="expandSubgraph: tenant_id"}
           11:59:35.039393      .     1 ProcessTaskOverNetwork. attr: create_time gid: 1, readTs: 2677287, node id: 9
           11:59:35.039395      .     2 End. Took 990ns  Attributes:{funcId=528783934, funcName="expandSubgraph: tenant_id"}
           11:59:35.039402      .     6 Start.  Attributes:{funcId=567134954, funcName="query.ProcessGraph.uid"}
           11:59:35.039402      .     0 ProcessTaskOverNetwork. attr: primary gid: 2, readTs: 2677287, node id: 9
           11:59:35.039405      .     2 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.039408      .     2 End. Took 2.595µs  Attributes:{funcId=567134954, funcName="query.ProcessGraph.uid"}
           11:59:35.039411      .     3 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.039425      .    13 invokeNetworkRequest: Sending request to dgraph-alpha-0.dgraph-alpha.crm-test.svc.cluster.local:7080
           11:59:35.039427      .     2 Zero uids for "tenant_id"
           11:59:35.039428      .     0 Start.  Attributes:{funcId=1400121861, funcName="query.ProcessGraph.source_id"}
           11:59:35.039433      .     4 ProcessTaskOverNetwork. attr: source_id gid: 2, readTs: 2677287, node id: 9
           11:59:35.039434      .     0 End. Took 877.927µs  Attributes:{funcId=10356715, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.039440      .     6 Zero uids for "source"
           11:59:35.039451      .    10 End. Took 1.695406ms  Attributes:{funcId=1999480660, funcName="query.ProcessGraph.source"}
           11:59:35.039472      .    21 Zero uids for "relation"
           11:59:35.039477      .     4 End. Took 5.054671ms  Attributes:{funcId=1779870991, funcName="query.ProcessGraph.relation"}
           11:59:35.039483      .     5 Zero uids for "account_relation"
           11:59:35.039487      .     4 End. Took 6.914228ms  Attributes:{funcId=420281850, funcName="query.ProcessGraph.account_relation"}
           11:59:35.039556      .    69 Start.  Attributes:{funcId=13998878, funcName="expandSubgraph: primary"}
           11:59:35.039572      .    15 Start.  Attributes:{funcId=672822786, funcName="expandSubgraph: source_id"}
           11:59:35.039578      .     5 End. Took 953ns  Attributes:{funcId=13998878, funcName="expandSubgraph: primary"}
           11:59:35.039581      .     3 End. Took 565ns  Attributes:{funcId=672822786, funcName="expandSubgraph: source_id"}
           11:59:35.039585      .     3 Zero uids for "primary"
           11:59:35.039591      .     6 End. Took 193.271µs  Attributes:{funcId=1575411271, funcName="query.ProcessGraph.primary"}
           11:59:35.039591      .     0 Zero uids for "source_id"
           11:59:35.039601      .     9 End. Took 170.739µs  Attributes:{funcId=1400121861, funcName="query.ProcessGraph.source_id"}
           11:59:35.039652      .    50 Start.  Attributes:{funcId=709699895, funcName="expandSubgraph: source_type"}
           11:59:35.039655      .     3 End. Took 783ns  Attributes:{funcId=709699895, funcName="expandSubgraph: source_type"}
           11:59:35.039660      .     4 Zero uids for "source_type"
           11:59:35.039665      .     4 End. Took 293.451µs  Attributes:{funcId=2124252579, funcName="query.ProcessGraph.source_type"}
           11:59:35.040118      .   453 Reply from server. len: 0 gid: 1 Attr: tenant_id
           11:59:35.040126      .     8 Start.  Attributes:{funcId=1159046032, funcName="expandSubgraph: tenant_id"}
           11:59:35.040129      .     3 End. Took 962ns  Attributes:{funcId=1159046032, funcName="expandSubgraph: tenant_id"}
           11:59:35.040154      .    24 Zero uids for "tenant_id"
           11:59:35.040159      .     5 End. Took 783.144µs  Attributes:{funcId=202025286, funcName="query.ProcessGraph.tenant_id"}
           11:59:35.040193      .    34 Reply from server. len: 0 gid: 1 Attr: create_time
           11:59:35.040203      .     9 Start.  Attributes:{funcId=173559392, funcName="expandSubgraph: create_time"}
           11:59:35.040206      .     3 End. Took 794ns  Attributes:{funcId=173559392, funcName="expandSubgraph: create_time"}
           11:59:35.040240      .    33 Zero uids for "create_time"
           11:59:35.040251      .    10 End. Took 860.482µs  Attributes:{funcId=515637624, funcName="query.ProcessGraph.create_time"}
           11:59:35.040311      .    59 Reply from server. len: 0 gid: 1 Attr: model_type
           11:59:35.040319      .     8 Start.  Attributes:{funcId=1055080453, funcName="expandSubgraph: model_type"}
           11:59:35.040322      .     3 End. Took 782ns  Attributes:{funcId=1055080453, funcName="expandSubgraph: model_type"}
           11:59:35.040351      .    28 Zero uids for "model_type"
           11:59:35.040356      .     4 End. Took 976.871µs  Attributes:{funcId=1690233459, funcName="query.ProcessGraph.model_type"}
           11:59:35.040361      .     5 Zero uids for "source"
           11:59:35.040365      .     3 End. Took 3.360451ms  Attributes:{funcId=1412810175, funcName="query.ProcessGraph.source"}
           11:59:35.040372      .     7 Zero uids for "relation"
           11:59:35.040375      .     3 End. Took 6.088114ms  Attributes:{funcId=1714434605, funcName="query.ProcessGraph.relation"}
           11:59:35.040382      .     6 Zero uids for "~account_relation"
           11:59:35.040386      .     4 End. Took 7.849659ms  Attributes:{funcId=1795994545, funcName="query.ProcessGraph.account_reverse.~account_relation"}
           11:59:35.040394      .     7 End. Took 10.109812ms  Attributes:{funcId=1492329636, funcName="query.ProcessGraph.reverse.~relation"}
           11:59:35.040400      .     6 End. Took 11.702271ms  Attributes:{funcId=1442029009, funcName="query.ProcessGraph.nodes.identity_id"}
           11:59:35.040468      .    67 End. Took 12.461666ms  Attributes:{funcId=1505875528, funcName="query.ProcessQuery"}
           11:59:35.040982      .   513 Response = {"nodes":[{"uid":"0x113738a","identity_id":"oM9O71Y-qV9G_Z3NZAnr6sXq1MKs","tenant_id":"26615263","namespace":"wechat","type":"open_id","create_time":"2021-05-08T06:47:14.280","reverse":[{"uid":"0x1137389","identity_id":"1573248426704275","tenant_id":"26615263","namespace":"cdp","type":"aff_id","create_time":"2021-05-08T06:47:14.629","relation":[{"uid":"0x113738a","identity_id":"oM9O71Y-qV9G_Z3NZAnr6sXq1MKs","tenant_id":"26615263","namespace":"wechat","type":"open_id","create_time":"2021-05-08T06:47:14.280","source":[{"uid":"0x113738b","source_id":"wx3f63feb6ed582c9b","source_type":"PUBLIC_NUMBER","create_time":"2021-05-08T06:47:14.280","primary":false,"tenant_id":"26615263"}]},{"uid":"0x113738c","identity_id":"okTgY5xovE5o1TE-2GGVosifBcHE","tenant_id":"26615263","namespace":"wechat","type":"union_id","create_time":"2021-05-08T06:47:14.280","source":[{"uid":"0x113738b","source_id":"wx3f63feb6ed582c9b","source_type":"PUBLIC_NUMBER","create_time":"2021-05-08T06:47:14.280","primary":false,"tenant_id":"
           11:59:35.041019      .    37   Attributes:{startTs=0}
2021/05/08-06:37:00.823393   125.052981 trace_id: 4b214a736c78e3c6392925e17030264f span_id: bf53ba5cb5a8696a
           06:37:00.823400      .     6 Request received: mutations:<set_nquads:"\r\n_:kYEqZY085a <type> \"aff_id\" .\r\n_:kYEqZY085a <namespace> \"cdp\" .\r\n_:kYEqZY085a <identity_id> \"1505814931620393\" .\r\n_:kYEqZY085a <create_time> \"2021-02-22T15:33:09.412\" .\r\n_:kYEqZY085a <tenant_id> \"lyf_test_2\" .\r\n_:kYEqZY085a <dgraph.type> \"Identity\" .\r\n_:kYEqZYzkli <type> \"phone\" .\r\n_:kYEqZYzkli <namespace> \"phone\" .\r\n_:kYEqZYzkli <identity_id> \"13366246858_1\" .\r\n_:kYEqZYzkli <create_time> \"2021-02-09T12:54:55.026\" .\r\n_:kYEqZYzkli <tenant_id> \"lyf_test_2\" .\r\n_:kYEqZYzkli <dgraph.type> \"Identity\" .\r\n_:kYEqZY085a <relation> _:kYEqZYzkli .\r\n_:kYEqZYQVtm <source_type> \"AFF_CRM\" .\r\n_:kYEqZYQVtm <source_id> \"-1\" .\r\n_:kYEqZYQVtm <create_time> \"2021-02-09T12:54:55.026\" .\r\n_:kYEqZYQVtm <tenant_id> \"lyf_test_2\" .\r\n_:kYEqZYQVtm <primary> \"false\" .\r\n_:kYEqZYQVtm <dgraph.type> \"Source\" .\r\n_:kYEqZYzkli <source> _:kYEqZYQVtm .\r\n  " > commit_now:true 
           06:37:00.829810      .  6410 Applying mutations: start_ts:2628278 edges:<entity:17983712 attr:"type" value:"aff_id" > edges:<entity:17983712 attr:"namespace" value:"cdp" > edges:<entity:17983712 attr:"identity_id" value:"1505814931620393" > edges:<entity:17983712 attr:"create_time" value:"2021-02-22T15:33:09.412" > edges:<entity:17983712 attr:"tenant_id" value:"lyf_test_2" > edges:<entity:17983712 attr:"dgraph.type" value:"Identity" > edges:<entity:17983713 attr:"type" value:"phone" > edges:<entity:17983713 attr:"namespace" value:"phone" > edges:<entity:17983713 attr:"identity_id" value:"13366246858_1" > edges:<entity:17983713 attr:"create_time" value:"2021-02-09T12:54:55.026" > edges:<entity:17983713 attr:"tenant_id" value:"lyf_test_2" > edges:<entity:17983713 attr:"dgraph.type" value:"Identity" > edges:<entity:17983712 attr:"relation" value_type:UID value_id:17983713 > edges:<entity:17983714 attr:"source_type" value:"AFF_CRM" > edges:<entity:17983714 attr:"source_id" value:"-1" > edges:<entity:17983714 attr:"create_time" value:"2021-02
           06:39:05.874926   125.045115 Txn Context: start_ts:2628278 keys:"15qyue1k2riv8" keys:"1895711491aeu" keys:"1b9tgk0jo9bap" keys:"1clbo9havpgjf" keys:"29dq8dvwc7cjb" keys:"2j1ulbsevwc76" keys:"2n3xbjnf2d5p7" keys:"2q01wcuha3ai8" keys:"2td2ihg5niqmj" keys:"2uvbup5w9gulz" keys:"2ywipsjj6bpwb" keys:"368gl8dw1kfei" keys:"3h11os9dv5okw" keys:"3h11os9dv5okx" keys:"86zczg10mvlk" keys:"nm7lt11f43c4" keys:"nm7lt11f43c6" keys:"nm7lt11f43c7" keys:"voi2sr4vjggi" keys:"wxl7a08j5tfc" keys:"ziu1bkm31qz4" keys:"1qmu37gggfzvo" keys:"1yp51n22ygf0" keys:"22dzp4ox6uwf4" keys:"2p5jxz9ixwhch" keys:"2uaxjx2it1bwi" keys:"336gtuv47rpk6" keys:"34gx5r327n7ht" keys:"35ksvzk4zbpph" keys:"3qyfhi55ie6co" keys:"3vsjv46jil6gk" keys:"7z1qswytttjm" keys:"f4j2s9a201e5" keys:"m7t9j1tok827" preds:"1-create_time" preds:"1-dgraph.type" preds:"1-namespace" preds:"1-relation" preds:"1-source" preds:"1-tenant_id" preds:"2-identity_id" preds:"2-primary" preds:"2-source_id" preds:"2-source_type" preds:"2-type" . Err=<nil>
           06:39:05.875018      .    92 Prewrites err: <nil>. Attempting to commit/abort immediately.
           06:39:05.876352      .  1334 Status of commit at ts: 2628278: Transaction has been aborted. Please retry
           06:39:05.876367      .    15   Attributes:{startTs=0}

Hi,@chewxy
Can you provide some explanation about the output information of zpages? Thank you.
能否提供一些关于zpages输出信息的说明?谢谢。

Checking the time-consuming worker.MutateOverNetwork log, it is found that it takes a lot of time to wait for the zero proposal, but the relevant indicators for querying the zero leader are normal, and the highest CPU utilization rate is 18%, because the zero leader needs to interact with multiple alphas , Is the processing speed of zero reaching the bottleneck?
查看耗时高的worker.MutateOverNetwork日志,发现其在等待zero 的proposal时的耗时较高,但查询zero leader的相关指标均正常,cpu最高使用率为18%,因为zero leader需要和多个alpha进行交互,是否是达到zero的处理速度达到瓶颈了呢
alpha-4:

alpha-3:

Can you also paste the node statistics? You can go to Ratel > Schema and then click on a Predicate, then see how many nodes there are in each predicate.

您还可以粘贴Predicate的statistics吗? 您可以转到Ratel>schema,然后单击一个Predicate. 右手边就有Usage & Statistics. 可以看每个Predicate 有多少node。若太多Predicate的话,10 个最大的Predicate就行了。

Ok.
Nodes with tenant_id 15898944
Nodes with create_time 15898944
Nodes with type 10629651
Nodes with identity_id 10629651
Nodes with namespace 10629649
Nodes with relation 5281065
Nodes with source 5281310
Nodes with source_id 5269296