log in sync writer (at detail level) and log room ids at info level

This commit is contained in:
Bruno Windels 2021-02-19 11:57:17 +01:00
parent 08622699f6
commit f4a3b64da0
3 changed files with 18 additions and 12 deletions

View file

@ -194,19 +194,17 @@ export class Sync {
const isInitialSync = !syncToken; const isInitialSync = !syncToken;
const roomStates = this._parseRoomsResponse(response.rooms, isInitialSync); const roomStates = this._parseRoomsResponse(response.rooms, isInitialSync);
log.set("roomCount", roomStates.length);
await log.wrap("prepare", log => this._prepareRooms(roomStates, log)); await log.wrap("prepare", log => this._prepareRooms(roomStates, log));
let sessionChanges; let sessionChanges;
await log.wrap("write", async log => { await log.wrap("write", async log => {
const syncTxn = this._openSyncTxn(); const syncTxn = this._openSyncTxn();
try { try {
sessionChanges = await log.wrap("session", log => this._session.writeSync(response, syncFilterId, syncTxn, log), log.level.Detail); sessionChanges = await log.wrap("session", log => this._session.writeSync(response, syncFilterId, syncTxn, log));
await Promise.all(roomStates.map(async rs => { await Promise.all(roomStates.map(async rs => {
rs.changes = await log.wrap("room", log => rs.room.writeSync( rs.changes = await log.wrap("room", log => rs.room.writeSync(
rs.roomResponse, isInitialSync, rs.preparation, syncTxn, log), log.level.Detail); rs.roomResponse, isInitialSync, rs.preparation, syncTxn, log));
})); }));
} catch(err) { } catch(err) {
// avoid corrupting state by only // avoid corrupting state by only

View file

@ -219,7 +219,7 @@ export class Room extends EventEmitter {
async writeSync(roomResponse, isInitialSync, {summaryChanges, decryptChanges, roomEncryption}, txn, log) { async writeSync(roomResponse, isInitialSync, {summaryChanges, decryptChanges, roomEncryption}, txn, log) {
log.set("id", this.id); log.set("id", this.id);
const {entries, newLiveKey, memberChanges} = const {entries, newLiveKey, memberChanges} =
await this._syncWriter.writeSync(roomResponse, txn); await log.wrap("syncWriter", log => this._syncWriter.writeSync(roomResponse, txn, log), log.level.Detail);
if (decryptChanges) { if (decryptChanges) {
const decryption = await decryptChanges.write(txn); const decryption = await decryptChanges.write(txn);
decryption.applyToEntries(entries); decryption.applyToEntries(entries);

View file

@ -106,7 +106,7 @@ export class SyncWriter {
* @param {Transaction} txn used to read and write from the fragment store * @param {Transaction} txn used to read and write from the fragment store
* @return {EventKey} the new event key to start writing events at * @return {EventKey} the new event key to start writing events at
*/ */
async _ensureLiveFragment(currentKey, entries, timeline, txn) { async _ensureLiveFragment(currentKey, entries, timeline, txn, log) {
if (!currentKey) { if (!currentKey) {
// means we haven't synced this room yet (just joined or did initial sync) // means we haven't synced this room yet (just joined or did initial sync)
@ -115,6 +115,7 @@ export class SyncWriter {
let liveFragment = await this._createLiveFragment(txn, timeline.prev_batch); let liveFragment = await this._createLiveFragment(txn, timeline.prev_batch);
currentKey = new EventKey(liveFragment.id, EventKey.defaultLiveKey.eventIndex); currentKey = new EventKey(liveFragment.id, EventKey.defaultLiveKey.eventIndex);
entries.push(FragmentBoundaryEntry.start(liveFragment, this._fragmentIdComparer)); entries.push(FragmentBoundaryEntry.start(liveFragment, this._fragmentIdComparer));
log.log({l: "live fragment", first: true, id: currentKey.fragmentId});
} else if (timeline.limited) { } else if (timeline.limited) {
// replace live fragment for limited sync, *only* if we had a live fragment already // replace live fragment for limited sync, *only* if we had a live fragment already
const oldFragmentId = currentKey.fragmentId; const oldFragmentId = currentKey.fragmentId;
@ -122,6 +123,7 @@ export class SyncWriter {
const {oldFragment, newFragment} = await this._replaceLiveFragment(oldFragmentId, currentKey.fragmentId, timeline.prev_batch, txn); const {oldFragment, newFragment} = await this._replaceLiveFragment(oldFragmentId, currentKey.fragmentId, timeline.prev_batch, txn);
entries.push(FragmentBoundaryEntry.end(oldFragment, this._fragmentIdComparer)); entries.push(FragmentBoundaryEntry.end(oldFragment, this._fragmentIdComparer));
entries.push(FragmentBoundaryEntry.start(newFragment, this._fragmentIdComparer)); entries.push(FragmentBoundaryEntry.start(newFragment, this._fragmentIdComparer));
log.log({l: "live fragment", limited: true, id: currentKey.fragmentId});
} }
return currentKey; return currentKey;
} }
@ -148,10 +150,11 @@ export class SyncWriter {
} }
} }
_writeStateEvents(roomResponse, memberChanges, txn) { _writeStateEvents(roomResponse, memberChanges, txn, log) {
// persist state // persist state
const {state} = roomResponse; const {state} = roomResponse;
if (Array.isArray(state?.events)) { if (Array.isArray(state?.events)) {
log.set("stateEvents", state.events.length);
for (const event of state.events) { for (const event of state.events) {
const memberChange = this._writeStateEvent(event, txn); const memberChange = this._writeStateEvent(event, txn);
if (memberChange) { if (memberChange) {
@ -161,11 +164,13 @@ export class SyncWriter {
} }
} }
async _writeTimeline(entries, timeline, currentKey, memberChanges, txn) { async _writeTimeline(entries, timeline, currentKey, memberChanges, txn, log) {
if (Array.isArray(timeline.events) && timeline.events.length) { if (Array.isArray(timeline.events) && timeline.events.length) {
// only create a fragment when we will really write an event // only create a fragment when we will really write an event
currentKey = await this._ensureLiveFragment(currentKey, entries, timeline, txn); currentKey = await this._ensureLiveFragment(currentKey, entries, timeline, txn, log);
const events = deduplicateEvents(timeline.events); const events = deduplicateEvents(timeline.events);
log.set("timelineEvents", events.length);
let timelineStateEventCount = 0;
for(const event of events) { for(const event of events) {
// store event in timeline // store event in timeline
currentKey = currentKey.nextKey(); currentKey = currentKey.nextKey();
@ -180,12 +185,14 @@ export class SyncWriter {
// process live state events first, so new member info is available // process live state events first, so new member info is available
if (typeof event.state_key === "string") { if (typeof event.state_key === "string") {
timelineStateEventCount += 1;
const memberChange = this._writeStateEvent(event, txn); const memberChange = this._writeStateEvent(event, txn);
if (memberChange) { if (memberChange) {
memberChanges.set(memberChange.userId, memberChange); memberChanges.set(memberChange.userId, memberChange);
} }
} }
} }
log.set("timelineStateEventCount", timelineStateEventCount);
} }
return currentKey; return currentKey;
} }
@ -218,14 +225,15 @@ export class SyncWriter {
* @param {Transaction} txn * @param {Transaction} txn
* @return {SyncWriterResult} * @return {SyncWriterResult}
*/ */
async writeSync(roomResponse, txn) { async writeSync(roomResponse, txn, log) {
const entries = []; const entries = [];
const {timeline} = roomResponse; const {timeline} = roomResponse;
const memberChanges = new Map(); const memberChanges = new Map();
// important this happens before _writeTimeline so // important this happens before _writeTimeline so
// members are available in the transaction // members are available in the transaction
this._writeStateEvents(roomResponse, memberChanges, txn); this._writeStateEvents(roomResponse, memberChanges, txn, log);
const currentKey = await this._writeTimeline(entries, timeline, this._lastLiveKey, memberChanges, txn); const currentKey = await this._writeTimeline(entries, timeline, this._lastLiveKey, memberChanges, txn, log);
log.set("memberChanges", memberChanges.size);
return {entries, newLiveKey: currentKey, memberChanges}; return {entries, newLiveKey: currentKey, memberChanges};
} }