a tool for shared writing and social publishing
add richer logging to push
+76
-7
+76
-7
app/api/rpc/[command]/push.ts
+76
-7
app/api/rpc/[command]/push.ts
···
63
63
let timeWaitingForLock: number;
64
64
let timeWaitingForDbConnection: number;
65
65
let timeProcessingMutations: number = 0;
66
+
let timeGettingClientGroup: number = 0;
67
+
let timeGettingTokenRights: number = 0;
68
+
let timeFlushingContext: number = 0;
69
+
let timeUpdatingLastMutations: number = 0;
70
+
let mutationTimings: Array<{
71
+
name: string;
72
+
duration: number;
73
+
}> = [];
66
74
67
75
let start = performance.now();
68
76
let client = await pool.connect();
···
80
88
start = performance.now();
81
89
try {
82
90
await db.transaction(async (tx) => {
91
+
let clientGroupStart = performance.now();
83
92
let clientGroup = await getClientGroup(tx, pushRequest.clientGroupID);
93
+
timeGettingClientGroup = performance.now() - clientGroupStart;
94
+
95
+
let tokenRightsStart = performance.now();
84
96
let token_rights = await tx
85
97
.select()
86
98
.from(permission_token_rights)
87
99
.where(eq(permission_token_rights.token, token.id));
100
+
timeGettingTokenRights = performance.now() - tokenRightsStart;
88
101
let { getContext, flush } = cachedServerMutationContext(
89
102
tx,
90
103
token.id,
···
92
105
);
93
106
94
107
let lastMutations = new Map<string, number>();
95
-
console.log(pushRequest.mutations.map((m) => m.name));
108
+
console.log(
109
+
`Processing ${pushRequest.mutations.length} mutations:`,
110
+
pushRequest.mutations.map((m) => m.name),
111
+
);
112
+
96
113
for (let mutation of pushRequest.mutations) {
97
114
let lastMutationID = clientGroup[mutation.clientID] || 0;
98
115
if (mutation.id <= lastMutationID) continue;
116
+
99
117
clientGroup[mutation.clientID] = mutation.id;
100
118
let name = mutation.name as keyof typeof mutations;
101
119
if (!mutations[name]) {
102
120
continue;
103
121
}
122
+
123
+
let mutationStart = performance.now();
104
124
try {
105
125
let ctx = getContext(mutation.clientID, mutation.id);
106
126
await mutations[name](mutation.args as any, ctx);
127
+
let mutationDuration = performance.now() - mutationStart;
128
+
mutationTimings.push({
129
+
name: mutation.name,
130
+
duration: mutationDuration,
131
+
});
107
132
} catch (e) {
133
+
let mutationDuration = performance.now() - mutationStart;
134
+
mutationTimings.push({
135
+
name: mutation.name,
136
+
duration: mutationDuration,
137
+
});
108
138
console.log(
109
-
`Error occured while running mutation: ${name}`,
139
+
`Error occurred while running mutation: ${name} after ${mutationDuration.toFixed(2)}ms`,
110
140
JSON.stringify(e),
111
141
JSON.stringify(mutation, null, 2),
112
142
);
···
114
144
lastMutations.set(mutation.clientID, mutation.id);
115
145
}
116
146
147
+
let dbUpdateStart = performance.now();
117
148
let lastMutationIdsUpdate = Array.from(lastMutations.entries()).map(
118
149
(entries) => ({
119
150
client_group: pushRequest.clientGroupID,
···
129
160
target: replicache_clients.client_id,
130
161
set: { last_mutation: sql`excluded.last_mutation` },
131
162
});
163
+
timeUpdatingLastMutations = performance.now() - dbUpdateStart;
164
+
165
+
let flushStart = performance.now();
132
166
await flush();
167
+
timeFlushingContext = performance.now() - flushStart;
133
168
});
134
169
timeProcessingMutations = performance.now() - start;
135
170
···
142
177
timeProcessingMutations = performance.now() - start;
143
178
console.log(e);
144
179
} finally {
145
-
console.log(
146
-
`Total Elapsed: ${timeProcessingMutations.toFixed(2)}ms
147
-
Time Waiting for DB Connection: ${timeWaitingForDbConnection.toFixed(2)}ms
148
-
Time Waiting For Lock: ${timeWaitingForLock.toFixed(2)}ms
149
-
`,
180
+
// Calculate mutation statistics
181
+
let totalMutationTime = mutationTimings.reduce(
182
+
(sum, m) => sum + m.duration,
183
+
0,
150
184
);
185
+
186
+
console.log(`
187
+
Push Request Performance Summary:
188
+
================================
189
+
Total Elapsed Time: ${timeProcessingMutations.toFixed(2)}ms
190
+
Time Waiting for DB Connection: ${timeWaitingForDbConnection.toFixed(2)}ms
191
+
Time Waiting For Lock: ${timeWaitingForLock.toFixed(2)}ms
192
+
Time Getting Client Group: ${timeGettingClientGroup.toFixed(2)}ms
193
+
Time Getting Token Rights: ${timeGettingTokenRights.toFixed(2)}ms
194
+
Time Updating Last Mutations: ${timeUpdatingLastMutations.toFixed(2)}ms
195
+
Time Flushing Context: ${timeFlushingContext.toFixed(2)}ms
196
+
197
+
Mutation Statistics:
198
+
===================
199
+
Total Mutations Processed: ${mutationTimings.length}
200
+
Total Mutation Execution Time: ${totalMutationTime.toFixed(2)}ms
201
+
Average Mutation Time: ${mutationTimings.length > 0 ? (totalMutationTime / mutationTimings.length).toFixed(2) : "0.00"}ms
202
+
203
+
Slowest Mutations:
204
+
${mutationTimings
205
+
.sort((a, b) => b.duration - a.duration)
206
+
.slice(0, 5)
207
+
.map((m) => ` ${m.name}: ${m.duration.toFixed(2)}ms`)
208
+
.join("\n")}
209
+
`);
210
+
211
+
if (mutationTimings.length > 10) {
212
+
console.log(
213
+
"\nDetailed Mutation Timings:",
214
+
mutationTimings.map((m) => ({
215
+
mutation: m.name,
216
+
duration: `${m.duration.toFixed(2)}ms`,
217
+
})),
218
+
);
219
+
}
151
220
client.release();
152
221
release();
153
222
supabase.removeChannel(channel);