Story about an effort to improve the performance of REQ in Nostream

This article is an English translation of a URL written in Japanese.
日本語で書かれた元記事はこちらです。Nostream のパフォーマンス改善に取り組んだ話

Nostr Advent Calendar 2023

This article is the 21st day of the Advent calendar in Nostr Advent Calendar 2023.
12/20 Yutaro's Nostr エクスペリエンスを最大化する方法は？
12/22 電子馬's

Introduction

Nostr is a new distributed social network (SNS) that enriches our communication. This innovative system allows us to freely exchange messages and content through multiple Nostr relays, enhancing censorship resistance and fault tolerance from the user and client perspective, making individual Nostr relay downtime not lead to a service shutdown.

However, the Nostr relay server I am working on faced a significant issue: the delay in processing search requests (REQs) via WebSocket, leading to extended processing times.

My Nostr relays:

• relay-jp.nostr.wirednet.jp
• relay.nostr.wirednet.jp
• ipv6.nostr.wirednet.jp

In this article, I will share how we tackled this problem and the results we achieved.

Problem Details

Performance Issues with JSONB Operator @>

In the Nostr relay server, a specification known as NIP is used for exchanging events and requests via WebSocket communication based on a common agreement (Nostr protocol). Among these, the search requests sent by clients, referred to as "REQ," involve filtering numerous events on the server side according to certain conditions, making it a heavy processing task.

Unfortunately, the implementation of the Nostream relay I use heavily utilized the JSONB @> operator for this process. This operator cannot leverage table indexes and requires a full table scan for every request, leading to a spike in CPU usage, especially when the data is abundant.

Problematic SQL in Slow Logs

As an example of the severity of the problem, here are some of the SQL statements frequently appearing in slow logs. These queries were used to search for events containing specific tags (e.g., #e or #p).

(select * from "events" where "event_kind" in ($1) and ("event_tags" @> $2 or "event_tags" @> $3 or "event_tags" @> $4 or "event_tags" @> $5 or "event_tags" @> $6 or "event_tags" @> $7 or "event_tags" @> $8 or "event_tags" @> $9 or "event_tags" @> $10 or "event_tags" @> $11 or "event_tags" @> $12 or "event_tags" @> $13 or "event_tags" @> $14 or "event_tags" @> $15 or "event_tags" @> $16 or "event_tags" @> $17 or "event_tags" @> $18 or "event_tags" @> $19 or "event_tags" @> $20 or "event_tags" @> $21 or "event_tags" @> $22 or "event_tags" @> $23 or "event_tags" @> $24 or "event_tags" @> $25 or "event_tags" @> $26 or "event_tags" @> $27 or "event_tags" @> $28 or "event_tags" @> $29 or "event_tags" @> $30 or "event_tags" @> $31 or "event_tags" @> $32 or "event_tags" @> $33 or "event_tags" @> $34 or "event_tags" @> $35 or "event_tags" @> $36 or "event_tags" @> $37 or "event_tags" @> $38 or "event_tags" @> $39 or "event_tags" @> $40 or "event_tags" @> $41 or "event_tags" @> $42 or "event_tags" @> $43 or "event_tags" @> $44 or "event_tags" @> $45 or "event_tags" @> $46 or "event_tags" @> $47 or "event_tags" @> $48 or "event_tags" @> $49 or "event_tags" @> $50 or "event_tags" @> $51 or "event_tags" @> $52 or "event_tags" @> $53 or "event_tags" @> $54 or "event_tags" @> $55 or "event_tags" @> $56 or "event_tags" @> $57 or "event_tags" @> $58 or "event_tags" @> $59 or "event_tags" @> $60 or "event_tags" @> $61 or "event_tags" @> $62 or "event_tags" @> $63 or "event_tags" @> $64 or "event_tags" @> $65 or "event_tags" @> $66 or "event_tags" @> $67 or "event_tags" @> $68 or "event_tags" @> $69 or "event_tags" @> $70 or "event_tags" @> $71 or "event_tags" @> $72 or "event_tags" @> $73 or "event_tags" @> $74 or "event_tags" @> $75 or "event_tags" @> $76)) union (select * from "events" where "event_kind" in ($77) and ("event_tags" @> $78 or "event_tags" @> $79 or "event_tags" @> $80 or "event_tags" @> $81 or "event_tags" @> $82 or "event_tags" @> $83 or "event_tags" @> $84 or "event_tags" @> $85 or "event_tags" @> $86 or "event_tags" @> $87 or "event_tags" @> $88 or "event_tags" @> $89 or "event_tags" @> $90 or "event_tags" @> $91 or "event_tags" @> $92 or "event_tags" @> $93 or "event_tags" @> $94 or "event_tags" @> $95 or "event_tags" @> $96 or "event_tags" @> $97 or "event_tags" @> $98 or "event_tags" @> $99 or "event_tags" @> $100 or "event_tags" @> $101 or "event_tags" @> $102 or "event_tags" @> $103 or "event_tags" @> $104 or "event_tags" @> $105 or "event_tags" @> $106 or "event_tags" @> $107 or "event_tags" @> $108 or "event_tags" @> $109 or "event_tags" @> $110 or "event_tags" @> $111 or "event_tags" @> $112 or "event_tags" @> $113 or "event_tags" @> $114 or "event_tags" @> $115 or "event_tags" @> $116 or "event_tags" @> $117 or "event_tags" @> $118 or "event_tags" @> $119 or "event_tags" @> $120 or "event_tags" @> $121 or "event_tags" @> $122 or "event_tags" @> $123 or "event_tags" @> $124 or "event_tags" @> $125 or "event_tags" @> $126 or "event_tags" @> $127 or "event_tags" @> $128 or "event_tags" @> $129 or "event_tags" @> $130 or "event_tags" @> $131 or "event_tags" @> $132 or "event_tags" @> $133 or "event_tags" @> $134 or "event_tags" @> $135 or "event_tags" @> $136 or "event_tags" @> $137 or "event_tags" @> $138 or "event_tags" @> $139 or "event_tags" @> $140 or "event_tags" @> $141 or "event_tags" @> $142 or "event_tags" @> $143 or "event_tags" @> $144 or "event_tags" @> $145 or "event_tags" @> $146 or "event_tags" @> $147 or "event_tags" @> $148 or "event_tags" @> $149 or "event_tags" @> $150 or "event_tags" @> $151 or "event_tags" @> $152) order by "event_created_at" asc limit $153) order by "event_created_at" asc limit $154

These queries use OR conditions for multiple tags, each employing the JSONB @> operator, significantly burdening the database's performance.

The Situation of the Problem

Such queries took a lot of time, often exceeding 30 seconds. Also, it was not uncommon for the server's overall CPU usage to reach 90-100%. This was a significant obstacle to the efficiency and scalability of the relay server.

Improvement Idea

While tweeting about the CPU spike in SQL query processing inside Nostream, @koteitan gave me an idea.

A relay that puts e tags in a hash table and index scans REQ when they come in, how about that?

This is it.

Implementation of the Improvement

Table Structure Before Improvements

Nostream had essentially only one standard table, the events table.

Design of the New event_tags Table

To improve the performance of the Nostr relay server, we first introduced a new table named event_tags. This table is designed to make the search for event tags more efficient.

CREATE TABLE IF NOT EXISTS public.event_tags
(
    id uuid NOT NULL DEFAULT uuid_generate_v4(),
    event_id bytea NOT NULL,
    tag_name text COLLATE pg_catalog."default" NOT NULL,
    tag_value text COLLATE pg_catalog."default" NOT NULL,
    CONSTRAINT event_tags_pkey PRIMARY KEY (id)
)
TABLESPACE pg_default;

ALTER TABLE IF EXISTS public.event_tags
    OWNER to nostr_ts_relay;

CREATE INDEX IF NOT EXISTS event_tags_tag_name_tag_value_index
    ON public.event_tags USING btree
    (tag_name COLLATE pg_catalog."default" ASC NULLS LAST, tag_value COLLATE pg_catalog."default" ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS event_tags_event_id_index
    ON public.event_tags USING btree
    (event_id ASC NULLS LAST)
    WITH (deduplicate_items=True)
    TABLESPACE pg_default;

This table stores the event ID, tag name, and tag value. Moreover, by indexing these fields, we significantly improved search efficiency.

Knex Migration Script

We created a Knex migration script to apply the database changes. This script handles the creation of the new table and the setting of indexes.

exports.up = async function (knex) {
  await knex.schema.createTable('event_tags', function (table) {
    table.uuid('id').primary().defaultTo(knex.raw('uuid_generate_v4()'));
    table.binary('event_id').notNullable();
    table.text('tag_name').notNullable();
    table.text('tag_value').notNullable();
  });

  await knex.schema.table('event_tags', function (table) {
    table.index(['tag_name', 'tag_value']);
  });

  await knex.schema.table('event_tags', function (table) {
    table.index(['event_id']);
  });
};

exports.down = function (knex) {
  return knex.schema.dropTable('event_tags');
};

Query Changes for Event Processing

Previously, the use of the JSONB operator led to performance degradation due to the inability to utilize indexes. As an improvement, we changed the event processing query to utilize the event_tags table.

src/repositories/event-repository.ts

--- a/src/repositories/event-repository.ts
+++ b/src/repositories/event-repository.ts
@@ -66,6 +66,8 @@ export class EventRepository implements IEventRepository {
     }
     const queries = filters.map((currentFilter) => {
       const builder = this.readReplicaDbClient<DBEvent>('events')
+        .leftJoin('event_tags', 'events.event_id', 'event_tags.event_id')
+        .select('events.*', 'event_tags.event_id as event_tags_event_id')
 
       forEachObjIndexed((tableFields: string[], filterName: string | number) => {
         builder.andWhere((bd) => {
@@ -107,7 +109,7 @@ export class EventRepository implements IEventRepository {
         })
       })({
         authors: ['event_pubkey', 'event_delegator'],
-        ids: ['event_id'],
+        ids: ['events.event_id'],
       })
 
       if (Array.isArray(currentFilter.kinds)) {
@@ -140,10 +142,8 @@ export class EventRepository implements IEventRepository {
               isEmpty,
               () => andWhereRaw('1 = 0', bd),
               forEach((criterion: string) => void orWhereRaw(
-                '"event_tags" @> ?',
-                [
-                  JSON.stringify([[filterName[1], criterion]]) as any,
-                ],
+                'event_tags.tag_name = ? AND event_tags.tag_value = ?',
+                [filterName[1], criterion],
                 bd,
               )),
             )(criteria)

Data Migration from the events Table to the event_tags Table

Ideally, the Knex migration script would include code to migrate the data from the event_tags field in the events table to the event_tags table.

However, due to the large number of events already saved on the Nostr relay, running the migration script would have taken a long time. Therefore, we didn't include it in the migration script and manually ran it in the background while the service was online. Naturally, during this time, REQs for unprocessed events would not hit, but clients would see the processing happening concurrently as they request the same REQ from multiple relay servers.

We were able to take this approach, leveraging the high fault tolerance of Nostr relay.

  const events = await knex.select('event_id', 'event_tags').from('events');
  const totalEvents = events.length;
  let processedEvents = 0;
  let lastPercentage = 0;

  for (const event of events) {
    for (const tag of event.event_tags) {
      const [tag_name, tag_value] = tag;
      if (tag_name.length === 1 && tag_value) {
        await knex('event_tags').insert({
          events_event_id: event.event_id,
          tag_name: tag_name,
          tag_value: tag_value
        });
      }
    }
    processedEvents++;
    const currentPercentage = Math.floor(processedEvents / totalEvents * 100);
    if (currentPercentage > lastPercentage) {
      console.log(`${new Date().toLocaleString()} Migration progress: ${currentPercentage}%`);
      lastPercentage = currentPercentage;
    }
  }

CREATE OR REPLACE FUNCTION process_event_tags_direct(event_row events) RETURNS VOID AS $$
DECLARE
  tag_element jsonb;
  tag_name text;
  tag_value text;
  exists_flag boolean;
BEGIN
  -- 既に処理されたevent_idがあればスキップ
  SELECT EXISTS(SELECT 1 FROM event_tags WHERE event_id = event_row.event_id) INTO exists_flag;
  IF exists_flag THEN
    RETURN;
  END IF;

  FOR tag_element IN SELECT jsonb_array_elements(event_row.event_tags)
  LOOP
    tag_name := trim((tag_element->0)::text, '"');
    tag_value := trim((tag_element->1)::text, '"');
    IF length(tag_name) = 1 AND tag_value IS NOT NULL AND tag_value <> '' THEN
      INSERT INTO event_tags (event_id, tag_name, tag_value) VALUES (event_row.event_id, tag_name, tag_value);
    END IF;
  END LOOP;
END;
$$ LANGUAGE plpgsql;

DO $$
DECLARE
  cur CURSOR FOR SELECT * FROM events ORDER BY event_id;
  row events%ROWTYPE;
  total_rows int;
  processed_rows int := 0;
BEGIN
  -- 全行数を取得
  SELECT count(*) INTO total_rows FROM events;

  OPEN cur;

  WHILE processed_rows < total_rows LOOP
    FOR i IN 1..100 LOOP
      FETCH NEXT FROM cur INTO row;
      EXIT WHEN NOT FOUND;

      -- process_event_tagsを直接呼び出す
      PERFORM process_event_tags_direct(row);

      processed_rows := processed_rows + 1;
    END LOOP;

    -- 進捗%を出力
    RAISE NOTICE 'Processed: %, Total: %, Remaining: %, Percentage: %', processed_rows, total_rows, total_rows - processed_rows, (processed_rows::float / total_rows::float * 100);
    -- 1秒待機
    PERFORM pg_sleep(0.1);
  END LOOP;

  CLOSE cur;
END $$;

It took about 6 hours to process approximately 13 million events in my 4-core machine environment.

Event Trigger

Although omitted in this article, the trigger is actually set to update the corresponding data in the event_tags table when a new event comes in or is updated.

src/repositories/event-repository.ts

CREATE OR REPLACE FUNCTION process_event_tags() RETURNS TRIGGER AS $$
DECLARE
  tag_element jsonb;
  tag_name text;
  tag_value text;
BEGIN
  DELETE FROM event_tags WHERE event_id = OLD.event_id;

  IF TG_OP = 'INSERT' OR TG_OP = 'UPDATE' THEN
    FOR tag_element IN SELECT jsonb_array_elements(NEW.event_tags)
    LOOP
      tag_name := trim((tag_element->0)::text, '"');
      tag_value := trim((tag_element->1)::text, '"');
      IF length(tag_name) = 1 AND tag_value IS NOT NULL AND tag_value <> '' THEN
        INSERT INTO event_tags (event_id, tag_name, tag_value) VALUES (NEW.event_id, tag_name, tag_value);
      END IF;
    END LOOP;
  END IF;

  RETURN NEW;
END;
$$ LANGUAGE plpgsql;

CREATE TRIGGER insert_event_tags
AFTER INSERT OR UPDATE OR DELETE ON events
FOR EACH ROW
EXECUTE FUNCTION process_event_tags();

Results After Improvement

Reduction in Slow Query Records

Before implementing the improvement, the Nostr relay server's slow logs frequently recorded SQL queries exceeding 30 seconds.

However, with the introduction of the event_tags table and the application of indexes, these slow queries were virtually eliminated. This is due to the shift from a full table

scan with the traditional JSONB operator to an efficient search using indexes.

Improvement in CPU Usage

The most notable effect of this improvement is the significant reduction in CPU usage. Before the improvement, the relay server's CPU usage hovered around 90-100%. After the improvement, it dropped to about 20-50%. This indicates a substantial reduction in database load.

This decrease in CPU usage directly translates to an overall performance improvement of the relay server. Especially in WebSocket communication, where near-real-time responses are required, such performance improvements significantly impact user experience.

Overall Performance Improvement

With these improvements, the relay server can now process more requests efficiently than before. Specifically, we achieved the following improvements:

• Shortened response time for REQ requests: The reduction in slow queries has resulted in faster responses to users.
• Improved scalability: With lower CPU usage, the same hardware resources can handle more requests, allowing the Nostr relay to accommodate an increasing number of users.

Conclusion

Through this article, we explored concrete solutions to the performance issues of the Nostr relay server. Efficient request processing and lower CPU usage significantly boost our future service offerings.

However, this is just the beginning. We expect the world of Nostr, a free SNS desired by many users, to continue growing through the cooperation and ingenuity of the user community. Let's build a better technological future together.