search

dgraph-io / dgraph

The high-performance database for modern applications
https://dgraph.io
Other
20.33k stars 1.49k forks source link

Rollups not happening as often as I think I should. #5036

Closed martinmr closed 4 years ago

martinmr commented 4 years ago

While I was testing incremental rollups I noticed the rollups happening when starting the cluster but they don't happen too often, even after sending hundreds of updates to different keys.

My first instinct was that sync pool that's used to store the batches keeps returning new lists so a batch rarely fills up. But I don't think it's likely.

I see the logs that say "operation started with id: opRollup". I think that happens every time there's a rollup but there's only about three of these lines in the log. And the last one does not have the corresponding log saying the task is finished. I am not sure if that means the task has not finished yet or that the task was cancelled. I am not too familiar with the code so I would like someone to take a second look. Maybe everything is working as designed.

martinmr commented 4 years ago

The logs if that's helpful

➜  compose git:(release/v20.03) ✗ docker-compose up
Starting alpha1 ... done
Starting zero1  ... done
Starting ratel  ... done
Attaching to alpha1, zero1, ratel
alpha1    | [Decoder]: Using assembly version of decoder
ratel     | 2020/03/25 20:01:51 Listening on port 8000...
zero1     | [Decoder]: Using assembly version of decoder
alpha1    | [Sentry] 2020/03/25 20:01:51 Integration installed: ContextifyFrames
alpha1    | [Sentry] 2020/03/25 20:01:51 Integration installed: Environment
alpha1    | [Sentry] 2020/03/25 20:01:51 Integration installed: Modules
alpha1    | [Sentry] 2020/03/25 20:01:51 Integration installed: IgnoreErrors
alpha1    | [Decoder]: Using assembly version of decoder
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: ContextifyFrames
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: Environment
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: Modules
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: IgnoreErrors
zero1     | [Decoder]: Using assembly version of decoder
alpha1    | [Sentry] 2020/03/25 20:01:52 Integration installed: ContextifyFrames
alpha1    | [Sentry] 2020/03/25 20:01:52 Integration installed: Environment
alpha1    | [Sentry] 2020/03/25 20:01:52 Integration installed: Modules
alpha1    | [Sentry] 2020/03/25 20:01:52 Integration installed: IgnoreErrors
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: ContextifyFrames
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: Environment
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: Modules
zero1     | [Sentry] 2020/03/25 20:01:52 Integration installed: IgnoreErrors
alpha1    | I0325 20:01:52.256153      17 init.go:98]
alpha1    |
alpha1    | Dgraph version   : v20.03.0-beta.20200320
alpha1    | Dgraph SHA-256   : cb43044ae806c952d23c1ae8ea402d170477b1622faf2e8f56619710ee74fe4f
alpha1    | Commit SHA-1     : cc10d2adb
alpha1    | Commit timestamp : 2020-03-20 16:18:05 -0700
alpha1    | Branch           : release/v20.03
alpha1    | Go version       : go1.14
alpha1    |
alpha1    | For Dgraph official documentation, visit https://docs.dgraph.io.
alpha1    | For discussions about Dgraph     , visit https://discuss.dgraph.io.
alpha1    | To say hi to the community       , visit https://dgraph.slack.com.
alpha1    |
alpha1    | Licensed variously under the Apache Public License 2.0 and Dgraph Community License.
alpha1    | Copyright 2015-2020 Dgraph Labs, Inc.
alpha1    |
alpha1    |
alpha1    | I0325 20:01:52.256173      17 run.go:606] x.Config: {PortOffset:100 QueryEdgeLimit:1000000 NormalizeNodeLimit:10000}
alpha1    | I0325 20:01:52.256191      17 run.go:607] x.WorkerConfig: {ExportPath:export NumPendingProposals:256 Tracing:1 MyAddr:alpha1:7180 ZeroAddr:zero1:5180 RaftId:1 WhiteListedIPRanges:[{Lower:10.0.0.0 Upper:10.255.255.255} {Lower:172.16.0.0 Upper:172.31.255.255} {Lower:192.168.0.0 Upper:192.168.255.255}] MaxRetries:-1 StrictMutations:false AclEnabled:false AbortOlderThan:5m0s SnapshotAfter:10 ProposedGroupId:0 StartTime:2020-03-25 20:01:52.00444331 +0000 UTC m=+0.006858522 LudicrousMode:false}
alpha1    | I0325 20:01:52.256224      17 run.go:608] worker.Config: {PostingDir:p BadgerTables:mmap BadgerVlog:mmap BadgerKeyFile: WALDir:w MutationsMode:0 AuthToken: AllottedMemory:1024 HmacSecret:[] AccessJwtTtl:0s RefreshJwtTtl:0s AclRefreshInterval:0s}
alpha1    | I0325 20:01:52.256282      17 server_state.go:74] Setting Badger table load option: mmap
alpha1    | I0325 20:01:52.256288      17 server_state.go:86] Setting Badger value log load option: mmap
alpha1    | I0325 20:01:52.256292      17 server_state.go:131] Opening write-ahead log BadgerDB with options: {Dir:w ValueDir:w SyncWrites:false TableLoadingMode:1 ValueLogLoadingMode:2 NumVersionsToKeep:1 ReadOnly:false Truncate:true Logger:0x26101a8 Compression:0 EventLogging:true InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1048576 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:10485760 MaxBfCacheSize:0 LoadBloomsOnOpen:true NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:10000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:1 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 managedTxns:false maxBatchCount:0 maxBatchSize:0}
alpha1    | I0325 20:01:52.258918      17 log.go:34] All 1 tables opened in 0s
alpha1    | I0325 20:01:52.259769      17 log.go:34] Replaying file id: 0 at offset: 22819
alpha1    | I0325 20:01:52.259786      17 log.go:34] Replay took: 1.942µs
alpha1    | I0325 20:01:52.259826      17 server_state.go:74] Setting Badger table load option: mmap
alpha1    | I0325 20:01:52.259833      17 server_state.go:86] Setting Badger value log load option: mmap
alpha1    | I0325 20:01:52.259838      17 server_state.go:154] Opening postings BadgerDB with options: {Dir:p ValueDir:p SyncWrites:false TableLoadingMode:2 ValueLogLoadingMode:2 NumVersionsToKeep:2147483647 ReadOnly:false Truncate:true Logger:0x26101a8 Compression:0 EventLogging:true InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1024 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:1073741824 MaxBfCacheSize:0 LoadBloomsOnOpen:true NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:1000000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:1 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 managedTxns:false maxBatchCount:0 maxBatchSize:0}
zero1     | I0325 20:01:52.355164      16 init.go:98]
zero1     |
zero1     | Dgraph version   : v20.03.0-beta.20200320
zero1     | Dgraph SHA-256   : cb43044ae806c952d23c1ae8ea402d170477b1622faf2e8f56619710ee74fe4f
zero1     | Commit SHA-1     : cc10d2adb
zero1     | Commit timestamp : 2020-03-20 16:18:05 -0700
zero1     | Branch           : release/v20.03
zero1     | Go version       : go1.14
zero1     |
zero1     | For Dgraph official documentation, visit https://docs.dgraph.io.
zero1     | For discussions about Dgraph     , visit https://discuss.dgraph.io.
zero1     | To say hi to the community       , visit https://dgraph.slack.com.
zero1     |
zero1     | Licensed variously under the Apache Public License 2.0 and Dgraph Community License.
zero1     | Copyright 2015-2020 Dgraph Labs, Inc.
zero1     |
zero1     |
zero1     | I0325 20:01:52.355214      16 run.go:105] Setting up grpc listener at: 0.0.0.0:5180
zero1     | I0325 20:01:52.355379      16 run.go:105] Setting up http listener at: 0.0.0.0:6180
zero1     | badger 2020/03/25 20:01:52 INFO: All 0 tables opened in 0s
zero1     | badger 2020/03/25 20:01:52 INFO: Replaying file id: 0 at offset: 0
zero1     | badger 2020/03/25 20:01:52 INFO: Replay took: 2.622673ms
zero1     | badger 2020/03/25 20:01:52 DEBUG: Value log discard stats empty
zero1     | I0325 20:01:52.362317      16 storage.go:261] Setting first index: 1
zero1     | I0325 20:01:52.362540      16 node.go:145] Setting raft.Config to: &{ID:1 peers:[] learners:[] ElectionTick:20 HeartbeatTick:1 Storage:0xc0003026f0 Applied:0 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x26101a8 DisableProposalForwarding:false}
zero1     | I0325 20:01:52.362742      16 node.go:314] Found hardstate: {Term:2 Vote:1 Commit:662 XXX_unrecognized:[]}
zero1     | I0325 20:01:52.362924      16 node.go:323] Group 0 found 663 entries
zero1     | I0325 20:01:52.362931      16 raft.go:447] Restarting node for dgraphzero
zero1     | I0325 20:01:52.362976      16 log.go:34] 1 became follower at term 2
zero1     | I0325 20:01:52.362997      16 log.go:34] newRaft 1 [peers: [], term: 2, commit: 662, applied: 0, lastindex: 662, lastterm: 2]
zero1     | I0325 20:01:52.363079      16 zero.go:98] Starting telemetry data collection for zero...
zero1     | I0325 20:01:52.363286      16 run.go:296] Running Dgraph Zero...
zero1     | I0325 20:01:52.364428      16 node.go:182] Setting conf state to nodes:1
zero1     | I0325 20:01:52.364516      16 raft.go:702] Done applying conf change at 0x1
zero1     | I0325 20:01:52.366095      16 pool.go:160] CONNECTING to alpha1:7180
zero1     | W0325 20:01:52.366495      16 pool.go:191] Shutting down extra connection to alpha1:7180
zero1     | W0325 20:01:52.367057      16 pool.go:254] Connection lost with alpha1:7180. Error: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 172.25.0.2:7180: connect: connection refused"
zero1     | W0325 20:01:52.367064      16 pool.go:254] Connection lost with alpha1:7180. Error: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 172.25.0.2:7180: connect: connection refused"
alpha1    | I0325 20:01:52.524159      17 log.go:34] All 153 tables opened in 257ms
alpha1    | I0325 20:01:52.526087      17 log.go:34] Replaying file id: 0 at offset: 162469015
alpha1    | I0325 20:01:52.526108      17 log.go:34] Replay took: 3.241µs
alpha1    | I0325 20:01:52.526957      17 groups.go:104] Current Raft Id: 0x1
alpha1    | I0325 20:01:52.526980      17 groups.go:627] No healthy Zero leader found. Trying to find a Zero leader...
alpha1    | I0325 20:01:52.527087      17 worker.go:96] Worker listening at address: [::]:7180
alpha1    | I0325 20:01:52.528210      17 run.go:477] Bringing up GraphQL HTTP API at 0.0.0.0:8180/graphql
alpha1    | I0325 20:01:52.528229      17 run.go:478] Bringing up GraphQL HTTP admin API at 0.0.0.0:8180/admin
alpha1    | I0325 20:01:52.528259      17 run.go:509] gRPC server started.  Listening on port 9180
alpha1    | I0325 20:01:52.528273      17 run.go:510] HTTP server started.  Listening on port 8180
alpha1    | I0325 20:01:52.528291      17 server.go:99] Starting telemetry data collection for alpha...
alpha1    | I0325 20:01:52.642910      17 pool.go:160] CONNECTING to zero1:5180
zero1     | I0325 20:01:52.644106      16 zero.go:417] Got connection request: cluster_info_only:true
zero1     | I0325 20:01:52.644193      16 log.go:34] 1 no leader at term 2; dropping index reading msg
zero1     | W0325 20:01:54.644232      16 node.go:671] [0x1] Read index context timed out
zero1     | I0325 20:01:54.644261      16 log.go:34] 1 no leader at term 2; dropping index reading msg
zero1     | I0325 20:01:55.563240      16 log.go:34] 1 is starting a new election at term 2
zero1     | I0325 20:01:55.563254      16 log.go:34] 1 became pre-candidate at term 2
zero1     | I0325 20:01:55.563257      16 log.go:34] 1 received MsgPreVoteResp from 1 at term 2
zero1     | I0325 20:01:55.563277      16 log.go:34] 1 became candidate at term 3
zero1     | I0325 20:01:55.563279      16 log.go:34] 1 received MsgVoteResp from 1 at term 3
zero1     | I0325 20:01:55.563296      16 log.go:34] 1 became leader at term 3
zero1     | I0325 20:01:55.563303      16 log.go:34] raft.node: 1 elected leader 1 at term 3
zero1     | I0325 20:01:55.563327      16 raft.go:667] I've become the leader, updating leases.
zero1     | I0325 20:01:55.563341      16 assign.go:42] Updated Lease id: 5130001. Txn Ts: 10001
zero1     | W0325 20:01:56.363334      16 raft.go:572] Zero node: 0x1 unable to reach quorum. Error: context deadline exceeded
zero1     | W0325 20:01:56.644285      16 node.go:671] [0x1] Read index context timed out
zero1     | I0325 20:01:56.644709      16 zero.go:435] Connected: cluster_info_only:true
alpha1    | I0325 20:01:56.645132      17 groups.go:664] Found connection to leader: zero1:5180
zero1     | I0325 20:01:56.645366      16 zero.go:417] Got connection request: id:1 group_id:1 addr:"alpha1:7180" force_group_id:true
zero1     | I0325 20:01:56.645667      16 zero.go:544] Connected: id:1 group_id:1 addr:"alpha1:7180" force_group_id:true
alpha1    | I0325 20:01:56.645950      17 groups.go:131] Connected to group zero. Assigned group: 1
alpha1    | I0325 20:01:56.645959      17 groups.go:133] Raft Id after connection to Zero: 0x1
alpha1    | I0325 20:01:56.646098      17 storage.go:261] Setting first index: 1
alpha1    | I0325 20:01:56.646106      17 draft.go:175] Node ID: 0x1 with GroupID: 1
alpha1    | I0325 20:01:56.646140      17 pool.go:160] CONNECTING to alpha1:7180
alpha1    | I0325 20:01:56.646134      17 node.go:145] Setting raft.Config to: &{ID:1 peers:[] learners:[] ElectionTick:20 HeartbeatTick:1 Storage:0xc0284ee960 Applied:0 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x26101a8 DisableProposalForwarding:false}
alpha1    | W0325 20:01:56.647129      17 pool.go:254] Connection lost with alpha1:7180. Error: rpc error: code = Unknown desc = No node has been set up yet
alpha1    | I0325 20:01:56.660065      17 node.go:314] Found hardstate: {Term:2 Vote:1 Commit:148 XXX_unrecognized:[]}
alpha1    | I0325 20:01:56.660184      17 node.go:323] Group 1 found 149 entries
alpha1    | I0325 20:01:56.660195      17 draft.go:1506] Restarting node for group: 1
alpha1    | I0325 20:01:56.660269      17 log.go:34] 1 became follower at term 2
alpha1    | I0325 20:01:56.660301      17 log.go:34] newRaft 1 [peers: [], term: 2, commit: 148, applied: 0, lastindex: 148, lastterm: 2]
alpha1    | I0325 20:01:56.660321      17 draft.go:1526] Restart node complete
alpha1    | I0325 20:01:56.660359      17 draft.go:136] Operation started with id: opRollup
alpha1    | I0325 20:01:56.660375      17 groups.go:151] Server is ready
alpha1    | I0325 20:01:56.660455      17 draft.go:925] Found Raft progress: 0
alpha1    | I0325 20:01:56.660473      17 groups.go:775] Got address of a Zero leader: zero1:5180
alpha1    | I0325 20:01:56.660629      17 groups.go:788] Starting a new membership stream receive from zero1:5180.
alpha1    | I0325 20:01:56.662040      17 node.go:182] Setting conf state to nodes:1
alpha1    | I0325 20:01:56.661531      17 groups.go:805] Received first state update from Zero: counter:662 groups:<key:1 value:<members:<key:1 value:<id:1 group_id:1 addr:"alpha1:7180" leader:true last_update:1585166479 > > tablets:<key:"actor.dubbing_performances" value:<group_id:1 predicate:"actor.dubbing_performances" > > tablets:<key:"actor.film" value:<group_id:1 predicate:"actor.film" > > tablets:<key:"apple_movietrailer_id" value:<group_id:1 predicate:"apple_movietrailer_id" > > tablets:<key:"art_direction_by" value:<group_id:1 predicate:"art_direction_by" > > tablets:<key:"art_director.films_art_directed" value:<group_id:1 predicate:"art_director.films_art_directed" > > tablets:<key:"casting_director" value:<group_id:1 predicate:"casting_director" > > tablets:<key:"casting_director.films_casting_directed" value:<group_id:1 predicate:"casting_director.films_casting_directed" > > tablets:<key:"character.portrayed_in_films" value:<group_id:1 predicate:"character.portrayed_in_films" > > tablets:<key:"character.portrayed_in_films_dubbed" value:<group_id:1 predicate:"character.portrayed_in_films_dubbed" > > tablets:<key:"cinematographer.film" value:<group_id:1 predicate:"cinematographer.film" > > tablets:<key:"cinematography" value:<group_id:1 predicate:"cinematography" > > tablets:<key:"collection.films_in_collection" value:<group_id:1 predicate:"collection.films_in_collection" > > tablets:<key:"collections" value:<group_id:1 predicate:"collections" > > tablets:<key:"company.films" value:<group_id:1 predicate:"company.films" > > tablets:<key:"company_role_or_service.companies_performing_this_role_or_service" value:<group_id:1 predicate:"company_role_or_service.companies_performing_this_role_or_service" > > tablets:<key:"content_rating.country" value:<group_id:1 predicate:"content_rating.country" > > tablets:<key:"content_rating.minimum_accompanied_age" value:<group_id:1 predicate:"content_rating.minimum_accompanied_age" > > tablets:<key:"content_rating.minimum_unaccompanied_age" value:<group_id:1 predicate:"content_rating.minimum_unaccompanied_age" > > tablets:<key:"content_rating.rating_system" value:<group_id:1 predicate:"content_rating.rating_system" > > tablets:<key:"content_rating_system.jurisdiction" value:<group_id:1 predicate:"content_rating_system.jurisdiction" > > tablets:<key:"content_rating_system.ratings" value:<group_id:1 predicate:"content_rating_system.ratings" > > tablets:<key:"costume_design_by" value:<group_id:1 predicate:"costume_design_by" > > tablets:<key:"costumer_designer.costume_design_for_film" value:<group_id:1 predicate:"costumer_designer.costume_design_for_film" > > tablets:<key:"country" value:<group_id:1 predicate:"country" > > tablets:<key:"crew_gig.crew_role" value:<group_id:1 predicate:"crew_gig.crew_role" > > tablets:<key:"crew_gig.crewmember" value:<group_id:1 predicate:"crew_gig.crewmember" > > tablets:<key:"crew_gig.film" value:<group_id:1 predicate:"crew_gig.film" > > tablets:<key:"crewmember.films_crewed" value:<group_id:1 predicate:"crewmember.films_crewed" > > tablets:<key:"cut.film" value:<group_id:1 predicate:"cut.film" > > tablets:<key:"cut.note" value:<group_id:1 predicate:"cut.note" > > tablets:<key:"cut.release_region" value:<group_id:1 predicate:"cut.release_region" > > tablets:<key:"cut.runtime" value:<group_id:1 predicate:"cut.runtime" > > tablets:<key:"cut.type_of_cut" value:<group_id:1 predicate:"cut.type_of_cut" > > tablets:<key:"dgraph.acl.rule" value:<group_id:1 predicate:"dgraph.acl.rule" > > tablets:<key:"dgraph.graphql.schema" value:<group_id:1 predicate:"dgraph.graphql.schema" > > tablets:<key:"dgraph.password" value:<group_id:1 predicate:"dgraph.password" > > tablets:<key:"dgraph.rule.permission" value:<group_id:1 predicate:"dgraph.rule.permission" > > tablets:<key:"dgraph.rule.predicate" value:<group_id:1 predicate:"dgraph.rule.predicate" > > tablets:<key:"dgraph.type" value:<group_id:1 predicate:"dgraph.type" > > tablets:<key:"dgraph.user.group" value:<group_id:1 predicate:"dgraph.user.group" > > tablets:<key:"dgraph.xid" value:<group_id:1 predicate:"dgraph.xid" > > tablets:<key:"director.film" value:<group_id:1 predicate:"director.film" > > tablets:<key:"distribution_medium.films_distributed_in_this_medium" value:<group_id:1 predicate:"distribution_medium.films_distributed_in_this_medium" > > tablets:<key:"distributor.films_distributed" value:<group_id:1 predicate:"distributor.films_distributed" > > tablets:<key:"distributors" value:<group_id:1 predicate:"distributors" > > tablets:<key:"dubbing_performances" value:<group_id:1 predicate:"dubbing_performances" > > tablets:<key:"edited_by" value:<group_id:1 predicate:"edited_by" > > tablets:<key:"editor.film" value:<group_id:1 predicate:"editor.film" > > tablets:<key:"email" value:<group_id:1 predicate:"email" > > tablets:<key:"estimated_budget" value:<group_id:1 predicate:"estimated_budget" > > tablets:<key:"executive_produced_by" value:<group_id:1 predicate:"executive_produced_by" > > tablets:<key:"fandango_id" value:<group_id:1 predicate:"fandango_id" > > tablets:<key:"featured_locations" value:<group_id:1 predicate:"featured_locations" > > tablets:<key:"featured_song" value:<group_id:1 predicate:"featured_song" > > tablets:<key:"featured_song.featured_in_film" value:<group_id:1 predicate:"featured_song.featured_in_film" > > tablets:<key:"featured_song.performed_by" value:<group_id:1 predicate:"featured_song.performed_by" > > tablets:<key:"festival.date_founded" value:<group_id:1 predicate:"festival.date_founded" > > tablets:<key:"festival.focus" value:<group_id:1 predicate:"festival.focus" > > tablets:<key:"festival.individual_festivals" value:<group_id:1 predicate:"festival.individual_festivals" > > tablets:<key:"festival.location" value:<group_id:1 predicate:"festival.location" > > tablets:<key:"festival.sponsoring_organization" value:<group_id:1 predicate:"festival.sponsoring_organization" > > tablets:<key:"festival_event.festival" value:<group_id:1 predicate:"festival_event.festival" > > tablets:<key:"festival_event.films" value:<group_id:1 predicate:"festival_event.films" > > tablets:<key:"festival_focus.festivals_with_this_focus" value:<group_id:1 predicate:"festival_focus.festivals_with_this_focus" > > tablets:<key:"festival_sponsor.festivals_sponsored" value:<group_id:1 predicate:"festival_sponsor.festivals_sponsored" > > tablets:<key:"festivals" value:<group_id:1 predicate:"festivals" > > tablets:<key:"filming" value:<group_id:1 predicate:"filming" > > tablets:<key:"format" value:<group_id:1 predicate:"format" > > tablets:<key:"format.format" value:<group_id:1 predicate:"format.format" > > tablets:<key:"genre" value:<group_id:1 predicate:"genre" > > tablets:<key:"gross_revenue" value:<group_id:1 predicate:"gross_revenue" > > tablets:<key:"http://www.w3.org/2000/01/rdf-schema#domain" value:<group_id:1 predicate:"http://www.w3.org/2000/01/rdf-schema#domain" > > tablets:<key:"http://www.w3.org/2000/01/rdf-schema#range" value:<group_id:1 predicate:"http://www.w3.org/2000/01/rdf-schema#range" > > tablets:<key:"http://www.w3.org/2002/07/owl#inverseOf" value:<group_id:1 predicate:"http://www.w3.org/2002/07/owl#inverseOf" > > tablets:<key:"initial_release_date" value:<group_id:1 predicate:"initial_release_date" > > tablets:<key:"job.films_with_this_crew_job" value:<group_id:1 predicate:"job.films_with_this_crew_job" > > tablets:<key:"language" value:<group_id:1 predicate:"language" > > tablets:<key:"loc" value:<group_id:1 predicate:"loc" > > tablets:<key:"location.featured_in_films" value:<group_id:1 predicate:"location.featured_in_films" > > tablets:<key:"locations" value:<group_id:1 predicate:"locations" > > tablets:<key:"metacritic_id" value:<group_id:1 predicate:"metacritic_id" > > tablets:<key:"music" value:<group_id:1 predicate:"music" > > tablets:<key:"music_contributor.film" value:<group_id:1 predicate:"music_contributor.film" > > tablets:<key:"name" value:<group_id:1 predicate:"name" > > tablets:<key:"netflix_id" value:<group_id:1 predicate:"netflix_id" > > tablets:<key:"nytimes_id" value:<group_id:1 predicate:"nytimes_id" > > tablets:<key:"other_companies" value:<group_id:1 predicate:"other_companies" > > tablets:<key:"other_crew" value:<group_id:1 predicate:"other_crew" > > tablets:<key:"performance.actor" value:<group_id:1 predicate:"performance.actor" > > tablets:<key:"performance.character" value:<group_id:1 predicate:"performance.character" > > tablets:<key:"performance.character_note" value:<group_id:1 predicate:"performance.character_note" > > tablets:<key:"performance.film" value:<group_id:1 predicate:"performance.film" > > tablets:<key:"performance.special_performance_type" value:<group_id:1 predicate:"performance.special_performance_type" > > tablets:<key:"person_or_entity_appearing_in_films" value:<group_id:1 predicate:"person_or_entity_appearing_in_films" > > tablets:<key:"personal_appearance.film" value:<group_id:1 predicate:"personal_appearance.film" > > tablets:<key:"personal_appearance.person" value:<group_id:1 predicate:"personal_appearance.person" > > tablets:<key:"personal_appearance.type_of_appearance" value:<group_id:1 predicate:"personal_appearance.type_of_appearance" > > tablets:<key:"personal_appearance_type.appearances" value:<group_id:1 predicate:"personal_appearance_type.appearances" > > tablets:<key:"personal_appearances" value:<group_id:1 predicate:"personal_appearances" > > tablets:<key:"post_production" value:<group_id:1 predicate:"post_production" > > tablets:<key:"pre_production" value:<group_id:1 predicate:"pre_production" > > tablets:<key:"prequel" value:<group_id:1 predicate:"prequel" > > tablets:<key:"primary_language" value:<group_id:1 predicate:"primary_language" > > tablets:<key:"produced_by" value:<group_id:1 predicate:"produced_by" > > tablets:<key:"producer.film" value:<group_id:1 predicate:"producer.film" > > tablets:<key:"producer.films_executive_produced" value:<group_id:1 predicate:"producer.films_executive_produced" > > tablets:<key:"production_companies" value:<group_id:1 predicate:"production_companies" > > tablets:<key:"production_company.films" value:<group_id:1 predicate:"production_company.films" > > tablets:<key:"production_design_by" value:<group_id:1 predicate:"production_design_by" > > tablets:<key:"production_designer.films_production_designed" value:<group_id:1 predicate:"production_designer.films_production_designed" > > tablets:<key:"rated" value:<group_id:1 predicate:"rated" > > tablets:<key:"rating" value:<group_id:1 predicate:"rating" > > tablets:<key:"regional_release_date.release_date" value:<group_id:1 predicate:"regional_release_date.release_date" > > tablets:<key:"regional_release_date.release_region" value:<group_id:1 predicate:"regional_release_date.release_region" > > tablets:<key:"release_date_s" value:<group_id:1 predicate:"release_date_s" > > tablets:<key:"rottentomatoes_id" value:<group_id:1 predicate:"rottentomatoes_id" > > tablets:<key:"runtime" value:<group_id:1 predicate:"runtime" > > tablets:<key:"sequel" value:<group_id:1 predicate:"sequel" > > tablets:<key:"series" value:<group_id:1 predicate:"series" > > tablets:<key:"series.films_in_series" value:<group_id:1 predicate:"series.films_in_series" > > tablets:<key:"set_decoration_by" value:<group_id:1 predicate:"set_decoration_by" > > tablets:<key:"set_designer.sets_designed" value:<group_id:1 predicate:"set_designer.sets_designed" > > tablets:<key:"song.films" value:<group_id:1 predicate:"song.films" > > tablets:<key:"song_performer.songs" value:<group_id:1 predicate:"song_performer.songs" > > tablets:<key:"songs" value:<group_id:1 predicate:"songs" > > tablets:<key:"soundtrack" value:<group_id:1 predicate:"soundtrack" > > tablets:<key:"special_performance_type.performance_type" value:<group_id:1 predicate:"special_performance_type.performance_type" > > tablets:<key:"starring" value:<group_id:1 predicate:"starring" > > tablets:<key:"story_by" value:<group_id:1 predicate:"story_by" > > tablets:<key:"story_contributor.story_credits" value:<group_id:1 predicate:"story_contributor.story_credits" > > tablets:<key:"subject.films" value:<group_id:1 predicate:"subject.films" > > tablets:<key:"subjects" value:<group_id:1 predicate:"subjects" > > tablets:<key:"tagline" value:<group_id:1 predicate:"tagline" > > tablets:<key:"topic_server.schemastaging_corresponding_entities_type" value:<group_id:1 predicate:"topic_server.schemastaging_corresponding_entities_type" > > tablets:<key:"topic_server.webref_cluster_members_type" value:<group_id:1 predicate:"topic_server.webref_cluster_members_type" > > tablets:<key:"traileraddict_id" value:<group_id:1 predicate:"traileraddict_id" > > tablets:<key:"trailers" value:<group_id:1 predicate:"trailers" > > tablets:<key:"type.property.expected_type" value:<group_id:1 predicate:"type.property.expected_type" > > tablets:<key:"type.property.reverse_property" value:<group_id:1 predicate:"type.property.reverse_property" > > tablets:<key:"type.property.schema" value:<group_id:1 predicate:"type.property.schema" > > tablets:<key:"writer.film" value:<group_id:1 predicate:"writer.film" > > tablets:<key:"written_by" value:<group_id:1 predicate:"written_by" > > checksum:13628474957856066072 > > zeros:<key:1 value:<id:1 addr:"zero1:5180" leader:true > > maxLeaseId:5130000 maxTxnTs:10000 cid:"2d2e992f-7c9d-4779-b598-84e052667a16" license:<maxNodes:18446744073709551615 expiryTs:1587753457 enabled:true >
alpha1    | I0325 20:01:56.672592      17 draft.go:136] Operation started with id: opIndexing
alpha1    | I0325 20:01:56.672618      17 draft.go:104] Operation completed with id: opIndexing
alpha1    | I0325 20:01:56.672672      17 draft.go:104] Operation completed with id: opRollup
alpha1    | I0325 20:01:57.660795      17 groups.go:183] Done informing Zero about the 142 tablets I have
alpha1    | I0325 20:01:57.660853      17 groups.go:216] Skipping initial schema upsert for predicate dgraph.type
alpha1    | I0325 20:01:57.660871      17 groups.go:216] Skipping initial schema upsert for predicate dgraph.graphql.schema
alpha1    | I0325 20:02:00.060809      17 log.go:34] 1 is starting a new election at term 2
alpha1    | I0325 20:02:00.060855      17 log.go:34] 1 became pre-candidate at term 2
alpha1    | I0325 20:02:00.060866      17 log.go:34] 1 received MsgPreVoteResp from 1 at term 2
alpha1    | I0325 20:02:00.060930      17 log.go:34] 1 became candidate at term 3
alpha1    | I0325 20:02:00.060942      17 log.go:34] 1 received MsgVoteResp from 1 at term 3
alpha1    | I0325 20:02:00.061057      17 log.go:34] 1 became leader at term 3
alpha1    | I0325 20:02:00.061092      17 log.go:34] raft.node: 1 elected leader 1 at term 3
alpha1    | I0325 20:02:00.660684      17 groups.go:856] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
alpha1    | I0325 20:02:00.660729      17 groups.go:865] Got Zero leader: zero1:5180
alpha1    | I0325 20:02:00.664685      17 admin.go:513] No GraphQL schema in Dgraph; serving empty GraphQL API
alpha1    | I0325 20:02:06.672736      17 draft.go:136] Operation started with id: opRollup
alpha1    | I0325 20:02:56.675338      17 draft.go:819] [0x1] Set Raft progress to index: 314.
alpha1    | I0325 20:02:56.726332      17 draft.go:523] Creating snapshot at index: 314. ReadTs: 10145.
alpha1    | I0325 20:02:56.726352      17 storage.go:595] CreateSnapshot i=314, cs=nodes:1
zero1     | I0325 20:03:05.672348      16 oracle.go:107] Purged below ts:10145, len(o.commits):0, len(o.rowCommit):5
alpha1    | I0325 20:03:56.661332      17 draft.go:819] [0x1] Set Raft progress to index: 390.
alpha1    | I0325 20:03:56.663253      17 draft.go:523] Creating snapshot at index: 390. ReadTs: 10207.
alpha1    | I0325 20:03:56.663292      17 storage.go:595] CreateSnapshot i=390, cs=nodes:1
zero1     | I0325 20:04:00.662595      16 oracle.go:107] Purged below ts:10207, len(o.commits):4, len(o.rowCommit):25
alpha1    | I0325 20:04:56.661244      17 draft.go:819] [0x1] Set Raft progress to index: 419.
alpha1    | I0325 20:04:56.673182      17 draft.go:523] Creating snapshot at index: 419. ReadTs: 10228.
alpha1    | I0325 20:04:56.673217      17 storage.go:595] CreateSnapshot i=419, cs=nodes:1
zero1     | I0325 20:05:06.672938      16 oracle.go:107] Purged below ts:10228, len(o.commits):0, len(o.rowCommit):5
alpha1    | I0325 20:06:56.660981      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:06:56.661030      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:06:56.688948      17 draft.go:1213] Sent tablet size update to Zero. Total size: 2.0 GB
alpha1    | I0325 20:07:56.661186      17 draft.go:819] [0x1] Set Raft progress to index: 431.
alpha1    | I0325 20:07:56.672245      17 draft.go:523] Creating snapshot at index: 431. ReadTs: 10228.
alpha1    | I0325 20:07:56.672273      17 storage.go:595] CreateSnapshot i=431, cs=nodes:1
alpha1    | I0325 20:09:56.661127      17 draft.go:819] [0x1] Set Raft progress to index: 592.
alpha1    | I0325 20:09:56.663497      17 draft.go:523] Creating snapshot at index: 592. ReadTs: 10380.
alpha1    | I0325 20:09:56.663537      17 storage.go:595] CreateSnapshot i=592, cs=nodes:1
zero1     | I0325 20:10:03.663271      16 oracle.go:107] Purged below ts:10380, len(o.commits):1, len(o.rowCommit):10
alpha1    | I0325 20:10:56.661619      17 draft.go:819] [0x1] Set Raft progress to index: 835.
alpha1    | I0325 20:10:56.673502      17 draft.go:523] Creating snapshot at index: 835. ReadTs: 10590.
alpha1    | I0325 20:10:56.673537      17 storage.go:595] CreateSnapshot i=835, cs=nodes:1
zero1     | I0325 20:10:58.671965      16 oracle.go:107] Purged below ts:10590, len(o.commits):0, len(o.rowCommit):5
zero1     | I0325 20:11:02.363552      16 storage.go:595] CreateSnapshot i=1073, cs=nodes:1
zero1     | I0325 20:11:02.368780      16 raft.go:616] Writing snapshot at index: 1073, applied mark: 1075
zero1     | I0325 20:11:52.363777      16 zero.go:118] Posting Telemetry data: &{Arch:amd64 Cid:2d2e992f-7c9d-4779-b598-84e052667a16 ClusterSize:2 DiskUsageMB:1910 NumAlphas:1 NumGroups:1 NumTablets:142 NumZeros:1 OS:linux SinceHours:0 Version:v20.03.0-beta.20200320 NumGraphQLPM:0 NumGraphQL:0}
alpha1    | I0325 20:11:52.528526      17 server.go:115] Posting Telemetry data: &{Arch:amd64 Cid:2d2e992f-7c9d-4779-b598-84e052667a16 ClusterSize:0 DiskUsageMB:0 NumAlphas:0 NumGroups:0 NumTablets:0 NumZeros:0 OS:linux SinceHours:0 Version:v20.03.0-beta.20200320 NumGraphQLPM:388 NumGraphQL:1}
zero1     | I0325 20:11:52.685690      16 telemetry.go:124] Telemetry response status: 201 Created
zero1     | I0325 20:11:52.685710      16 telemetry.go:125] Telemetry response body: {"created": true}
alpha1    | I0325 20:11:52.821491      17 telemetry.go:124] Telemetry response status: 201 Created
alpha1    | I0325 20:11:52.821525      17 telemetry.go:125] Telemetry response body: {"created": true}
alpha1    | I0325 20:11:56.660624      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:11:56.660643      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:11:56.660659      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:11:56.661050      17 draft.go:819] [0x1] Set Raft progress to index: 944.
alpha1    | I0325 20:11:56.661194      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:11:56.662201      17 draft.go:1213] Sent tablet size update to Zero. Total size: 2.0 GB
alpha1    | I0325 20:11:56.662392      17 draft.go:523] Creating snapshot at index: 944. ReadTs: 10700.
alpha1    | I0325 20:11:56.662408      17 storage.go:595] CreateSnapshot i=944, cs=nodes:1
zero1     | I0325 20:12:04.713142      16 oracle.go:107] Purged below ts:10700, len(o.commits):9, len(o.rowCommit):50
alpha1    | I0325 20:12:43.400578      17 groups.go:491] Serving tablet for: test
alpha1    | I0325 20:12:56.661236      17 draft.go:819] [0x1] Set Raft progress to index: 1010.
alpha1    | I0325 20:12:56.672574      17 draft.go:523] Creating snapshot at index: 1010. ReadTs: 10753.
alpha1    | I0325 20:12:56.672621      17 storage.go:595] CreateSnapshot i=1010, cs=nodes:1
zero1     | I0325 20:12:59.663197      16 oracle.go:107] Purged below ts:10753, len(o.commits):0, len(o.rowCommit):1
alpha1    | I0325 20:13:17.732503      17 http.go:560] Got alter request via HTTP from 172.25.0.1:40080
alpha1    | I0325 20:13:17.732631      17 server.go:135] Received ALTER op: schema:"<test>: string @index(term) ."
alpha1    | I0325 20:13:17.733209      17 server.go:275] Got schema: &{Preds:[predicate:"test" value_type:STRING directive:INDEX tokenizer:"term" ] Types:[]}
alpha1    | I0325 20:13:17.742029      17 draft.go:136] Operation started with id: opIndexing
alpha1    | I0325 20:13:17.742054      17 index.go:851] Deleting index for attr test and tokenizers []
alpha1    | I0325 20:13:17.742059      17 index.go:865] Deleting index for attr test and tokenizers [term]
alpha1    | I0325 20:13:17.742070      17 log.go:34] Writes flushed. Stopping compactions now...
alpha1    | I0325 20:13:17.742096      17 draft.go:104] Operation completed with id: opRollup
alpha1    | I0325 20:13:17.764716      17 log.go:34] Got compaction priority: {level:0 score:1.74 dropPrefix:[0 0 4 116 101 115 116 2 1]}
alpha1    | I0325 20:13:17.764748      17 log.go:34] Running for level: 0
alpha1    | I0325 20:13:18.084883      17 log.go:34] LOG Compact 0->1, del 3 tables, add 2 tables, took 320.115441ms
alpha1    | I0325 20:13:18.084920      17 log.go:34] Compaction for level: 0 DONE
alpha1    | I0325 20:13:18.119536      17 log.go:34] LOG Compact 1->1, del 1 tables, add 1 tables, took 34.580515ms
alpha1    | I0325 20:13:18.119583      17 log.go:34] DropPrefix done
alpha1    | I0325 20:13:18.119592      17 log.go:34] Resuming writes
alpha1    | I0325 20:13:18.119607      17 log.go:34] Writes flushed. Stopping compactions now...
alpha1    | I0325 20:13:18.159542      17 log.go:34] LOG Compact 1->1, del 1 tables, add 1 tables, took 39.091794ms
alpha1    | I0325 20:13:18.159590      17 log.go:34] DropPrefix done
alpha1    | I0325 20:13:18.159601      17 log.go:34] Resuming writes
alpha1    | I0325 20:13:18.159642      17 index.go:896] Rebuilding index for attr test and tokenizers [term]
alpha1    | I0325 20:13:18.160241      17 index.go:545] Rebuilding indexes using the temp folder /tmp/dgraph_index_305160239
alpha1    | I0325 20:13:18.168026      17 log.go:34] All 0 tables opened in 0s
alpha1    | I0325 20:13:18.168789      17 index.go:562] Rebuilding index for predicate test: Starting process. StartTs=10763. Prefix=
alpha1    | 00000000  00 00 04 74 65 73 74 00                           |...test.|
alpha1    |
alpha1    | I0325 20:13:18.169162      17 log.go:34] Rebuilding index for predicate test (1/2): Created batch of size: 492 B in 76.641µs.
alpha1    | I0325 20:13:18.169172      17 log.go:34] Rebuilding index for predicate test (1/2): Sent 12 keys
alpha1    | I0325 20:13:18.169813      17 index.go:636] Rebuilding index for predicate test: building temp index took: 1.00986ms
alpha1    | I0325 20:13:18.169826      17 index.go:640] Rebuilding index for predicate test: writing index to badger
alpha1    | I0325 20:13:18.169922      17 log.go:34] Rebuilding index for predicate test (2/2): Created batch of size: 222 B in 14.929µs.
alpha1    | I0325 20:13:18.169930      17 log.go:34] Rebuilding index for predicate test (2/2): Sent 1 keys
alpha1    | I0325 20:13:18.169936      17 index.go:684] Rebuilding index for predicate test: Flushing all writes.
alpha1    | I0325 20:13:18.170665      17 index.go:643] Rebuilding index for predicate test: writing index took: 833.845µs
alpha1    | I0325 20:13:18.180169      17 log.go:34] Got compaction priority: {level:0 score:1.73 dropPrefix:[]}
alpha1    | I0325 20:13:18.180194      17 log.go:34] Running for level: 0
alpha1    | I0325 20:13:18.192152      17 log.go:34] LOG Compact 0->1, del 1 tables, add 1 tables, took 11.944275ms
alpha1    | I0325 20:13:18.192171      17 log.go:34] Compaction for level: 0 DONE
alpha1    | I0325 20:13:18.192179      17 log.go:34] Force compaction on level 0 done
alpha1    | I0325 20:13:18.194541      17 mutation.go:178] Done schema update predicate:"test" value_type:STRING directive:INDEX tokenizer:"term"
alpha1    | I0325 20:13:18.194658      17 draft.go:104] Operation completed with id: opIndexing
alpha1    | I0325 20:13:20.159822      17 server.go:290] ALTER op: schema:"<test>: string @index(term) ."  done
alpha1    | I0325 20:13:28.194870      17 draft.go:136] Operation started with id: opRollup
alpha1    | I0325 20:13:56.661319      17 draft.go:819] [0x1] Set Raft progress to index: 1103.
alpha1    | I0325 20:13:56.662955      17 draft.go:523] Creating snapshot at index: 1103. ReadTs: 10842.
alpha1    | I0325 20:13:56.662986      17 storage.go:595] CreateSnapshot i=1103, cs=nodes:1
zero1     | I0325 20:14:05.672279      16 oracle.go:107] Purged below ts:10842, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:14:56.661483      17 draft.go:819] [0x1] Set Raft progress to index: 1154.
alpha1    | I0325 20:14:56.673367      17 draft.go:523] Creating snapshot at index: 1154. ReadTs: 10889.
alpha1    | I0325 20:14:56.673414      17 storage.go:595] CreateSnapshot i=1154, cs=nodes:1
zero1     | I0325 20:15:00.672674      16 oracle.go:107] Purged below ts:10889, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:15:56.661393      17 draft.go:819] [0x1] Set Raft progress to index: 1174.
alpha1    | I0325 20:15:56.673090      17 draft.go:523] Creating snapshot at index: 1174. ReadTs: 10901.
alpha1    | I0325 20:15:56.673125      17 storage.go:595] CreateSnapshot i=1174, cs=nodes:1
zero1     | I0325 20:16:06.672344      16 oracle.go:107] Purged below ts:10901, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:16:56.661036      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:16:56.661127      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:16:56.715873      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:21:56.660968      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:21:56.661055      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:21:56.664046      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:26:56.661045      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:26:56.661148      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:26:56.664383      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:31:56.660884      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:31:56.660960      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:31:56.664235      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:36:56.660987      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:36:56.661050      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:36:56.664142      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:41:56.660957      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:41:56.661048      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:41:56.664460      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:46:56.660959      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:46:56.661064      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:46:56.664353      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:48:56.662163      17 draft.go:819] [0x1] Set Raft progress to index: 1360.
alpha1    | I0325 20:48:56.667087      17 draft.go:523] Creating snapshot at index: 1360. ReadTs: 11071.
alpha1    | I0325 20:48:56.667131      17 storage.go:595] CreateSnapshot i=1360, cs=nodes:1
zero1     | I0325 20:49:06.662588      16 oracle.go:107] Purged below ts:11071, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:49:56.661662      17 draft.go:819] [0x1] Set Raft progress to index: 1515.
alpha1    | I0325 20:49:56.673221      17 draft.go:523] Creating snapshot at index: 1515. ReadTs: 11208.
alpha1    | I0325 20:49:56.673264      17 storage.go:595] CreateSnapshot i=1515, cs=nodes:1
zero1     | I0325 20:50:01.672405      16 oracle.go:107] Purged below ts:11208, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:50:56.660739      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:50:56.661377      17 draft.go:819] [0x1] Set Raft progress to index: 1589.
alpha1    | I0325 20:50:56.661532      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:50:56.662910      17 draft.go:523] Creating snapshot at index: 1589. ReadTs: 11274.
alpha1    | I0325 20:50:56.662926      17 storage.go:595] CreateSnapshot i=1589, cs=nodes:1
zero1     | I0325 20:51:07.671798      16 oracle.go:107] Purged below ts:11274, len(o.commits):17, len(o.rowCommit):36
alpha1    | I0325 20:51:49.829495      17 groups.go:491] Serving tablet for: test2
alpha1    | I0325 20:51:56.661110      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:51:56.661202      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:51:56.661999      17 draft.go:819] [0x1] Set Raft progress to index: 1726.
alpha1    | I0325 20:51:56.664783      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:51:56.674058      17 draft.go:523] Creating snapshot at index: 1726. ReadTs: 11394.
alpha1    | I0325 20:51:56.674089      17 storage.go:595] CreateSnapshot i=1726, cs=nodes:1
zero1     | I0325 20:52:02.662709      16 oracle.go:107] Purged below ts:11394, len(o.commits):0, len(o.rowCommit):1
alpha1    | I0325 20:52:56.661941      17 draft.go:819] [0x1] Set Raft progress to index: 1826.
alpha1    | I0325 20:52:56.664350      17 draft.go:523] Creating snapshot at index: 1826. ReadTs: 11484.
alpha1    | I0325 20:52:56.664375      17 storage.go:595] CreateSnapshot i=1826, cs=nodes:1
zero1     | I0325 20:52:57.672277      16 oracle.go:107] Purged below ts:11484, len(o.commits):0, len(o.rowCommit):1
alpha1    | I0325 20:53:56.663010      17 draft.go:819] [0x1] Set Raft progress to index: 1990.
alpha1    | I0325 20:53:56.676142      17 draft.go:523] Creating snapshot at index: 1990. ReadTs: 11632.
alpha1    | I0325 20:53:56.676217      17 storage.go:595] CreateSnapshot i=1990, cs=nodes:1
zero1     | I0325 20:54:03.672289      16 oracle.go:107] Purged below ts:11632, len(o.commits):0, len(o.rowCommit):1
alpha1    | I0325 20:54:56.662485      17 draft.go:819] [0x1] Set Raft progress to index: 2398.
alpha1    | I0325 20:54:56.676540      17 draft.go:523] Creating snapshot at index: 2398. ReadTs: 12002.
alpha1    | I0325 20:54:56.676577      17 storage.go:595] CreateSnapshot i=2398, cs=nodes:1
zero1     | I0325 20:54:58.673437      16 oracle.go:107] Purged below ts:12002, len(o.commits):0, len(o.rowCommit):1
alpha1    | I0325 20:55:56.661753      17 draft.go:819] [0x1] Set Raft progress to index: 2434.
alpha1    | I0325 20:55:56.674835      17 draft.go:523] Creating snapshot at index: 2434. ReadTs: 12032.
alpha1    | I0325 20:55:56.674908      17 storage.go:595] CreateSnapshot i=2434, cs=nodes:1
zero1     | I0325 20:56:04.673580      16 oracle.go:107] Purged below ts:12032, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 20:56:56.660716      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:56:56.660743      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 20:56:56.660773      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 20:56:56.660994      17 draft.go:819] [0x1] Set Raft progress to index: 2498.
alpha1    | I0325 20:56:56.661035      17 draft.go:1347] Num pending txns: 1
alpha1    | I0325 20:56:56.661972      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 20:56:56.661981      17 draft.go:523] Creating snapshot at index: 2498. ReadTs: 12089.
alpha1    | I0325 20:56:56.661988      17 storage.go:595] CreateSnapshot i=2498, cs=nodes:1
zero1     | I0325 20:56:59.661727      16 oracle.go:107] Purged below ts:12089, len(o.commits):15, len(o.rowCommit):32

alpha1    | I0325 20:57:56.662245      17 draft.go:819] [0x1] Set Raft progress to index: 2779.
alpha1    | I0325 20:57:56.665852      17 draft.go:523] Creating snapshot at index: 2779. ReadTs: 12343.
alpha1    | I0325 20:57:56.665889      17 storage.go:595] CreateSnapshot i=2779, cs=nodes:1
zero1     | I0325 20:58:05.663853      16 oracle.go:107] Purged below ts:12343, len(o.commits):0, len(o.rowCommit):2
alpha1    | I0325 21:01:56.660963      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 21:01:56.661055      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 21:01:56.664625      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 21:06:56.661072      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 21:06:56.661183      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 21:06:56.665117      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
alpha1    | I0325 21:11:56.661068      17 draft.go:1169] Calculating tablet sizes. Found 153 tables
alpha1    | I0325 21:11:56.661183      17 draft.go:1178] Unable to parse key: Invalid size 25185 for key [33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 254]
alpha1    | I0325 21:11:56.664935      17 draft.go:1213] Sent tablet size update to Zero. Total size: 3.0 GB
martinmr commented 4 years ago

I had the snapshot_after parameter set very low so I removed it and restarted the cluster. I still see the issue despite mutating and querying more than the keys in the batch.

martinmr commented 4 years ago

@parasssh Thanks for the help. The rollups are happening. It was just there were no very frequent logs.

parasssh commented 4 years ago

I verified that rollups are happening as expected with the increment tool.

As far as I can tell, it is working as expected. The log message may be misleading. "operation started with id: opRollup" -- this means the go routine to rollup keys is running. It does not necessarily mean keys are bring rolled up. "operation completed with id: opRollup" --- this means the go routine is stopped. Rollups are obviously paused here.

So, here is what is happening:

  1. Rollup Operation is started [this does not necessarily mean rollup is happening. It just means that the go routine that processes rollup is running]
  2. Indexing Operation is started.
  3. This preempts the rollup operation and the go routine is stopped. So, no rollups shall happen.
  4. Indexing Operation is completed.
  5. Now, rollup operation is started after 10 sec. (again this just means the go routine that processes rollup is running)

Note: We should not expect a completed rollup message now unless a Indexing or Snapshot task comes in. In other words, when no other operation is running, opRollup is started forever.