Skip to content

Commit

Permalink
Log conversation job wait time and duration
Browse files Browse the repository at this point in the history
  • Loading branch information
@indutny-signal
indutny-signal committed Jun 14, 2021
1 parent 2674e2f commit 61ac79e
Show file tree
Hide file tree
Showing 6 changed files with 116 additions and 76 deletions.
2 changes: 1 addition & 1 deletion js/deletes.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,7 @@
}

// Do not await, since this can deadlock the queue
targetConversation.queueJob(async () => {
targetConversation.queueJob('Deletes.onDelete', async () => {
window.log.info('Handling DOE for', del.get('targetSentTimestamp'));

const messages = await window.Signal.Data.getMessagesBySentAt(
Expand Down
105 changes: 54 additions & 51 deletions js/reactions.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -65,67 +65,70 @@
}

// awaiting is safe since `onReaction` is never called from inside the queue
return await targetConversation.queueJob(async () => {
window.log.info(
'Handling reaction for',
reaction.get('targetTimestamp')
);

const messages = await window.Signal.Data.getMessagesBySentAt(
reaction.get('targetTimestamp'),
{
MessageCollection: Whisper.MessageCollection,
}
);
// Message is fetched inside the conversation queue so we have the
// most recent data
const targetMessage = messages.find(m => {
const contact = m.getContact();

if (!contact) {
return false;
}

const mcid = contact.get('id');
const recid = ConversationController.ensureContactIds({
uuid: reaction.get('targetAuthorUuid'),
});
return mcid === recid;
});

if (!targetMessage) {
return await targetConversation.queueJob(
'Reactions.onReaction',
async () => {
window.log.info(
'No message for reaction',
reaction.get('targetAuthorUuid'),
'Handling reaction for',
reaction.get('targetTimestamp')
);

// Since we haven't received the message for which we are removing a
// reaction, we can just remove those pending reactions
if (reaction.get('remove')) {
this.remove(reaction);
const oldReaction = this.where({
targetAuthorUuid: reaction.get('targetAuthorUuid'),
targetTimestamp: reaction.get('targetTimestamp'),
emoji: reaction.get('emoji'),
const messages = await window.Signal.Data.getMessagesBySentAt(
reaction.get('targetTimestamp'),
{
MessageCollection: Whisper.MessageCollection,
}
);
// Message is fetched inside the conversation queue so we have the
// most recent data
const targetMessage = messages.find(m => {
const contact = m.getContact();

if (!contact) {
return false;
}

const mcid = contact.get('id');
const recid = ConversationController.ensureContactIds({
uuid: reaction.get('targetAuthorUuid'),
});
oldReaction.forEach(r => this.remove(r));
}
return mcid === recid;
});

return undefined;
}
if (!targetMessage) {
window.log.info(
'No message for reaction',
reaction.get('targetAuthorUuid'),
reaction.get('targetTimestamp')
);

// Since we haven't received the message for which we are removing a
// reaction, we can just remove those pending reactions
if (reaction.get('remove')) {
this.remove(reaction);
const oldReaction = this.where({
targetAuthorUuid: reaction.get('targetAuthorUuid'),
targetTimestamp: reaction.get('targetTimestamp'),
emoji: reaction.get('emoji'),
});
oldReaction.forEach(r => this.remove(r));
}

return undefined;
}

const message = MessageController.register(
targetMessage.id,
targetMessage
);
const message = MessageController.register(
targetMessage.id,
targetMessage
);

const oldReaction = await message.handleReaction(reaction);
const oldReaction = await message.handleReaction(reaction);

this.remove(reaction);
this.remove(reaction);

return oldReaction;
});
return oldReaction;
}
);
} catch (error) {
window.log.error(
'Reactions.onReaction error:',
Expand Down
12 changes: 7 additions & 5 deletions ts/background.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -162,7 +162,7 @@ export async function startApp(): Promise<void> {
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const e164 = c.get('e164')!;

c.queueJob(async () => {
c.queueJob('sendDeliveryReceipt', async () => {
try {
const {
wrap,
Expand Down Expand Up @@ -850,7 +850,7 @@ export async function startApp(): Promise<void> {
if (conversation) {
const receivedAt = Date.now();
const receivedAtCounter = window.Signal.Util.incrementMessageCounter();
conversation.queueJob(() =>
conversation.queueJob('addDeliveryIssue', () =>
conversation.addDeliveryIssue({
receivedAt,
receivedAtCounter,
Expand Down Expand Up @@ -2838,7 +2838,9 @@ export async function startApp(): Promise<void> {
);
}

sender.queueJob(() => sender.sendProfileKeyUpdate());
sender.queueJob('sendProfileKeyUpdate', () =>
sender.sendProfileKeyUpdate()
);
});
},

Expand Down Expand Up @@ -3730,7 +3732,7 @@ export async function startApp(): Promise<void> {
window.log.warn(
`requestResend/${logId}: No content hint, adding error immediately`
);
conversation.queueJob(async () => {
conversation.queueJob('addDeliveryIssue', async () => {
conversation.addDeliveryIssue({
receivedAt: receivedAtDate,
receivedAtCounter,
Expand Down Expand Up @@ -3778,7 +3780,7 @@ export async function startApp(): Promise<void> {

const receivedAt = Date.now();
const receivedAtCounter = window.Signal.Util.incrementMessageCounter();
conversation.queueJob(async () => {
conversation.queueJob('addChatSessionRefreshed', async () => {
conversation.addChatSessionRefreshed({ receivedAt, receivedAtCounter });
});
}
Expand Down
10 changes: 5 additions & 5 deletions ts/groups.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1259,7 +1259,7 @@ export async function modifyGroupV2({
window.log.info(`modifyGroupV2/${idLog}: Queuing attempt ${attempt}`);

// eslint-disable-next-line no-await-in-loop
await conversation.queueJob(async () => {
await conversation.queueJob('modifyGroupV2', async () => {
window.log.info(`modifyGroupV2/${idLog}: Running attempt ${attempt}`);

const actions = await createGroupChange();
Expand Down Expand Up @@ -1670,7 +1670,7 @@ export async function createGroupV2({
}
);

await conversation.queueJob(() => {
await conversation.queueJob('storageServiceUploadJob', () => {
window.Signal.Services.storageServiceUploadJob();
});

Expand Down Expand Up @@ -2023,7 +2023,7 @@ export async function initiateMigrationToGroupV2(
await maybeFetchNewCredentials();

try {
await conversation.queueJob(async () => {
await conversation.queueJob('initiateMigrationToGroupV2', async () => {
const ACCESS_ENUM =
window.textsecure.protobuf.AccessControl.AccessRequired;

Expand Down Expand Up @@ -2310,7 +2310,7 @@ export async function waitThenRespondToGroupV2Migration(
// Then wait to process all outstanding messages for this conversation
const { conversation } = options;

await conversation.queueJob(async () => {
await conversation.queueJob('waitThenRespondToGroupV2Migration', async () => {
try {
// And finally try to migrate the group
await respondToGroupV2Migration(options);
Expand Down Expand Up @@ -2698,7 +2698,7 @@ export async function waitThenMaybeUpdateGroup(
return;
}

await conversation.queueJob(async () => {
await conversation.queueJob('waitThenMaybeUpdateGroup', async () => {
try {
// And finally try to update the group
await maybeUpdateGroup(options, { viaSync });
Expand Down
61 changes: 48 additions & 13 deletions ts/models/conversations.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,6 +89,8 @@ const { addStickerPackReference } = window.Signal.Data;
const THREE_HOURS = 3 * 60 * 60 * 1000;
const FIVE_MINUTES = 1000 * 60 * 5;

const JOB_REPORTING_THRESHOLD_MS = 25;

const ATTRIBUTES_THAT_DONT_INVALIDATE_PROPS_CACHE = new Set([
'profileLastFetchedAt',
]);
Expand Down Expand Up @@ -1051,7 +1053,9 @@ export class ConversationModel extends window.Backbone
this.setRegistered();

// If we couldn't apply universal timer before - try it again.
this.queueJob(() => this.maybeSetPendingUniversalTimer());
this.queueJob('maybeSetPendingUniversalTimer', () =>
this.maybeSetPendingUniversalTimer()
);
}

isValid(): boolean {
Expand Down Expand Up @@ -1168,7 +1172,7 @@ export class ConversationModel extends window.Backbone
return;
}

await this.queueJob(async () => {
await this.queueJob('sendTypingMessage', async () => {
const recipientId = isDirectConversation(this.attributes)
? this.getSendTarget()
: undefined;
Expand Down Expand Up @@ -2154,19 +2158,25 @@ export class ConversationModel extends window.Backbone
setVerifiedDefault(options?: VerificationOptions): Promise<unknown> {
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const { DEFAULT } = this.verifiedEnum!;
return this.queueJob(() => this._setVerified(DEFAULT, options));
return this.queueJob('setVerifiedDefault', () =>
this._setVerified(DEFAULT, options)
);
}

setVerified(options?: VerificationOptions): Promise<unknown> {
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const { VERIFIED } = this.verifiedEnum!;
return this.queueJob(() => this._setVerified(VERIFIED, options));
return this.queueJob('setVerified', () =>
this._setVerified(VERIFIED, options)
);
}

setUnverified(options: VerificationOptions): Promise<unknown> {
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const { UNVERIFIED } = this.verifiedEnum!;
return this.queueJob(() => this._setVerified(UNVERIFIED, options));
return this.queueJob('setUnverified', () =>
this._setVerified(UNVERIFIED, options)
);
}

async _setVerified(
Expand Down Expand Up @@ -2863,7 +2873,7 @@ export class ConversationModel extends window.Backbone

// Lastly, we don't send read syncs for any message marked read due to a read
// sync. That's a notification explosion we don't need.
return this.queueJob(() =>
return this.queueJob('onReadMessage', () =>
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
this.markRead(message.get('received_at')!, {
sendReadReceipts: false,
Expand Down Expand Up @@ -2936,15 +2946,38 @@ export class ConversationModel extends window.Backbone
return null;
}

queueJob(callback: () => unknown | Promise<unknown>): Promise<WhatIsThis> {
queueJob(
name: string,
callback: () => unknown | Promise<unknown>
): Promise<WhatIsThis> {
this.jobQueue = this.jobQueue || new window.PQueue({ concurrency: 1 });

const taskWithTimeout = window.textsecure.createTaskWithTimeout(
callback,
`conversation ${this.idForLogging()}`
);

return this.jobQueue.add(taskWithTimeout);
const queuedAt = Date.now();
return this.jobQueue.add(async () => {
const startedAt = Date.now();
const waitTime = startedAt - queuedAt;

if (waitTime > JOB_REPORTING_THRESHOLD_MS) {
window.log.info(
`Conversation job ${name} was blocked for ${waitTime}ms`
);
}

try {
return await taskWithTimeout();
} finally {
const duration = Date.now() - startedAt;

if (duration > JOB_REPORTING_THRESHOLD_MS) {
window.log.info(`Conversation job ${name} took ${duration}ms`);
}
}
});
}

isAdmin(conversationId: string): boolean {
Expand Down Expand Up @@ -3232,7 +3265,7 @@ export class ConversationModel extends window.Backbone
const destination = this.getSendTarget()!;
const recipients = this.getRecipients();

return this.queueJob(async () => {
return this.queueJob('sendDeleteForEveryone', async () => {
window.log.info(
'Sending deleteForEveryone to conversation',
this.idForLogging(),
Expand Down Expand Up @@ -3362,7 +3395,7 @@ export class ConversationModel extends window.Backbone
const destination = this.getSendTarget()!;
const recipients = this.getRecipients();

return this.queueJob(async () => {
return this.queueJob('sendReactionMessage', async () => {
window.log.info(
'Sending reaction to conversation',
this.idForLogging(),
Expand Down Expand Up @@ -3559,7 +3592,7 @@ export class ConversationModel extends window.Backbone
const destination = this.getSendTarget()!;
const recipients = this.getRecipients();

this.queueJob(async () => {
this.queueJob('sendMessage', async () => {
const now = timestamp || Date.now();

await this.maybeApplyUniversalTimer();
Expand Down Expand Up @@ -3756,7 +3789,9 @@ export class ConversationModel extends window.Backbone
return;
}

this.queueJob(() => this.maybeSetPendingUniversalTimer());
this.queueJob('maybeSetPendingUniversalTimer', () =>
this.maybeSetPendingUniversalTimer()
);

const ourConversationId = window.ConversationController.getOurConversationId();
if (!ourConversationId) {
Expand Down Expand Up @@ -5018,7 +5053,7 @@ export class ConversationModel extends window.Backbone
);
this.set({ needsStorageServiceSync: true });

this.queueJob(() => {
this.queueJob('captureChange', () => {
Services.storageServiceUploadJob();
});
}
Expand Down
2 changes: 1 addition & 1 deletion ts/models/messages.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3507,7 +3507,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {

// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const conversation = window.ConversationController.get(conversationId)!;
return conversation.queueJob(async () => {
return conversation.queueJob('handleDataMessage', async () => {
window.log.info(
`Starting handleDataMessage for message ${message.idForLogging()} in conversation ${conversation.idForLogging()}`
);
Expand Down

0 comments on commit 61ac79e

Please sign in to comment.