Add some performance profiling, increase performance for loading thumbnail data

package.json

@@ -1,6 +1,6 @@
 {
   "name": "moshing-mammut",
-  "version": "2.1.0",
+  "version": "2.1.1",
   "private": true,
   "license": "LGPL-3.0-or-later",
   "scripts": {

src/lib/server/db.ts

@@ -67,8 +67,7 @@ type Migration = {
   name: string;
   statement: string;
 };
-
+const db: sqlite3.Database = new sqlite3.cached.Database('moshingmammut.db');
-const db: sqlite3.Database = new sqlite3.Database('moshingmammut.db');
 
 export function close() {
   try {
@@ -660,12 +659,15 @@ function getSongThumbnailData(
   thumbUrls: string[]
 ): Promise<Map<string, SongThumbnailImage[]>> {
   return new Promise((resolve, reject) => {
+    const start = performance.now();
     db.all(
       `SELECT song_thumbnailUrl, file, sizeDescriptor, kind
       FROM songsthumbnails
       WHERE song_thumbnailUrl IN (${thumbUrlsParams});`,
       thumbUrls,
       (err, rows: SongThumbnailAvatarRow[]) => {
+        const afterQuery = performance.now();
+        logger.verbose('thumbnail query took', afterQuery - start, 'ms');
         if (err != null) {
           logger.error('Error loading avatars', err);
           reject(err);
@@ -687,6 +689,8 @@ function getSongThumbnailData(
           },
           new Map()
         );
+        const afterReduce = performance.now();
+        logger.verbose('thumbnail reduce took', afterReduce - afterQuery, 'ms');
         resolve(thumbnailMap);
       }
     );
@@ -730,10 +734,16 @@ export async function getPosts(
   before: string | null,
   limit: number
 ): Promise<Post[]> {
+  const start = performance.now();
   if (!databaseReady) {
     await waitReady();
   }
-  return await getPostsInternal(since, before, limit);
+  const ready = performance.now();
+  logger.debug('DB ready took', ready - start, 'ms');
+  const posts = await getPostsInternal(since, before, limit);
+  const afterPosts = performance.now();
+  logger.debug('DB posts', afterPosts - ready, 'ms');
+  return posts;
 }
 
 async function getPostsInternal(
@@ -741,6 +751,7 @@ async function getPostsInternal(
   before: string | null,
   limit: number
 ): Promise<Post[]> {
+  const start = performance.now();
   let filterQuery = '';
   const params: FilterParameter = { $limit: limit };
   if (since === null && before === null) {
@@ -763,8 +774,12 @@ async function getPostsInternal(
     params[acctParam] = ignoredUser;
     params[usernameParam] = ignoredUser;
   });
+  const afterFilter = performance.now();
+  logger.debug('filterQuery took', afterFilter - start, 'ms');
 
   const rows = await getPostData(filterQuery, params);
+  const afterRows = performance.now();
+  logger.debug('rows took', afterRows - afterFilter, 'ms');
   if (rows.length === 0) {
     // No need to check for tags and songs
     return [];
@@ -772,19 +787,45 @@ async function getPostsInternal(
 
   const postIdsParams = rows.map(() => '?').join(', ');
   const postIds = rows.map((r: PostRow) => r.url);
+  const afterParams = performance.now();
+  logger.debug('params took', afterParams - afterRows, 'ms');
+
   const tagMap = await getTagData(postIdsParams, postIds);
+  const afterTag = performance.now();
+  logger.debug('rows took', afterTag - afterRows, 'ms');
+
   const songMap = await getSongData(postIdsParams, postIds);
-  for (const entry of songMap) {
+  const afterSong = performance.now();
-    for (const songInfo of entry[1]) {
+  logger.debug('rows took', afterSong - afterTag, 'ms');
-      const thumbs = await getSongThumbnails(songInfo);
+
-      songInfo.resizedThumbnails = thumbs;
+  const turls = songMap
+    .values()
+    .flatMap((x) => x)
+    .map((x) => x.thumbnailUrl)
+    .filter((x) => x !== undefined)
+    .toArray();
+  if (turls) {
+    const tMap = await getSongThumbnailData('?, '.repeat(turls.length).slice(0, -2), turls);
+    for (const entry of songMap) {
+      for (const songInfo of entry[1]) {
+        if (songInfo.thumbnailUrl === undefined) {
+          continue;
+        }
+        const thumbs = tMap.get(songInfo.thumbnailUrl) ?? [];
+        songInfo.resizedThumbnails = thumbs;
+      }
     }
   }
+  const afterThumbs2 = performance.now();
+  logger.debug('thumbs took', afterThumbs2 - afterSong, 'ms');
 
   const accountUrls = [...new Set(rows.map((r: PostRow) => r.account_url))];
   const accountUrlsParams = accountUrls.map(() => '?').join(', ');
 
   const avatars = await getAvatarData(accountUrlsParams, accountUrls);
+  const afterAvatar = performance.now();
+  logger.debug('avatar took', afterAvatar - afterThumbs2, 'ms');
+
   const posts = rows.map((row) => {
     return {
       id: row.id,
@@ -804,6 +845,8 @@ async function getPostsInternal(
       songs: songMap.get(row.url) || []
     } as Post;
   });
+  const afterMap = performance.now();
+  logger.debug('map took', afterMap - afterAvatar, 'ms');
   return posts;
 }
 

src/routes/+page.ts

@@ -2,11 +2,19 @@ import type { Post } from '$lib/mastodon/response';
 import type { PageLoad } from './$types';
 
 export const load = (async ({ fetch, setHeaders }) => {
+  const start = performance.now();
   const p = await fetch('/');
+  const afterFetch = performance.now();
+  console.debug('+page.ts: Fetch took', afterFetch - start, 'ms');
   setHeaders({
     'cache-control': 'public,max-age=60'
   });
+  const afterHeaders = performance.now();
+  console.debug('+page.ts: Headers took', afterHeaders - afterFetch, 'ms');
+  const j: Post[] = await p.json();
+  const afterJson = performance.now();
+  console.debug('+page.ts: JSON took', afterJson - afterHeaders, 'ms');
   return {
-    posts: (await p.json()) as Post[]
+    posts: j
   };
 }) satisfies PageLoad;

src/routes/+server.ts

@@ -1,8 +1,17 @@
+import { Logger } from '$lib/log';
 import type { RequestHandler } from './$types';
 
+const logger = new Logger('+server.ts /');
+
 export const GET = (async ({ fetch, setHeaders }) => {
+  const start = performance.now();
   setHeaders({
     'cache-control': 'max-age=10'
   });
-  return await fetch('api/posts');
+  const afterHeaders = performance.now();
+  logger.debug('Headers took', afterHeaders - start, 'ms');
+  const f = await fetch('api/posts?count=5');
+  const afterFetch = performance.now();
+  logger.debug('Fetch took', afterFetch - afterHeaders, 'ms');
+  return f;
 }) satisfies RequestHandler;

src/routes/api/posts/+server.ts

@@ -1,16 +1,28 @@
 import { getPosts } from '$lib/server/db';
 import { json } from '@sveltejs/kit';
+import { Logger } from '$lib/log';
 
 import type { RequestHandler } from './$types';
+import { performance } from 'perf_hooks';
+
+const logger = new Logger('+server.ts API');
 
 export const GET = (async ({ url }) => {
+  const start = performance.now();
   const since = url.searchParams.get('since');
   const before = url.searchParams.get('before');
   let count = Number.parseInt(url.searchParams.get('count') || '');
   if (isNaN(count)) {
-    count = 20;
+    count = 10;
   }
   count = Math.min(count, 100);
+  const afterCount = performance.now();
+  logger.debug('Count took', afterCount - start, 'ms');
   const posts = await getPosts(since, before, count);
-  return json(posts);
+  const afterFetch = performance.now();
+  logger.debug('DB took', afterFetch - afterCount, 'ms');
+  const resp = json(posts);
+  const afterResponse = performance.now();
+  logger.debug('Response took', afterResponse - afterFetch, 'ms');
+  return resp;
 }) satisfies RequestHandler;