自作 Cisco Unified IP Phone Services Application を Apache Bench にかけながら改良する

# はじめに
これは[前回の記事](https://qiita.com/CIB-MC/items/b046c23014203b704655)からの続きです。

とりあえずやっつけで Cisco Unified IP Phone Services Application (長い) を作ってみましたが、アクセスがあるたびに Node.js で表示用の画像を作ってるのでパフォーマンスが気になります。
ほら、もしかしたら数百人いる環境で使われるかもしれないし。(などと)

# テスト先環境
- ProLiant TM200 (Intel(R) Xeon(R) CPU D-1518) から 仮想2コア
- Debian 12.4
- Node.js v18.19.0

# Apache Bench で計測してみる

- リクエスト総数: 10000
- 同時リクエスト数: 200
- Lengthエラー報告: 無効

※ すなわちコマンドとしては `ab -n 10000 -c 200 -l テスト先URL`
※ Lengthエラー報告を無効にしているのは、アクセスするタイミングでエオルゼア時間が変わるためです。(エオルゼア時間が違う ＝ 画像が違う)

## ケース1:対策無し
アクセスがあるたびに愚直に下記のような画像を生成して応答する場合を計測してみましょう。

![et1.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/2066798/68719b21-8338-4ff8-92a7-8d009fdb4445.png)


```text:et1.png
Document Path:          /api/et1.png
Document Length:        Variable

Concurrency Level:      200
Time taken for tests:   42.979 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      19671292 bytes
HTML transferred:       18221292 bytes
Requests per second:    232.67 [#/sec] (mean)
Time per request:       859.583 [ms] (mean)
Time per request:       4.298 [ms] (mean, across all concurrent requests)
Transfer rate:          446.97 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.1      1      11
Processing:    14  854 205.2    883    1614
Waiting:        6  854 205.2    882    1614
Total:         15  855 205.2    884    1614

Percentage of the requests served within a certain time (ms)
  50%    884
  66%    909
  75%    937
  80%    963
  90%   1050
  95%   1081
  98%   1118
  99%   1457
 100%   1614 (longest request)
```

……うん、ひどいですね。
最大で約1.6秒も遅れるようでは時計として成立しません。(個人の感想です)

## ケース2:送る画像をモノクロPNGにしてみる

どうせ画像内で白と黒しか使ってないので下記のようなモノクロ画像にして送信してみるのはどうでしょう？

![et2.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/2066798/e04b1441-911d-c694-66c8-9d9a5eb17041.png)


```text:et2.png
Document Path:          /api/et2.png
Document Length:        Variable

Concurrency Level:      200
Time taken for tests:   19.664 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      6144377 bytes
HTML transferred:       4694377 bytes
Requests per second:    508.54 [#/sec] (mean)
Time per request:       393.287 [ms] (mean)
Time per request:       1.966 [ms] (mean, across all concurrent requests)
Transfer rate:          305.14 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   0.8      1       8
Processing:    12  390  86.1    401     751
Waiting:        4  390  86.1    401     751
Total:         13  391  86.2    402     754

Percentage of the requests served within a certain time (ms)
  50%    402
  66%    424
  75%    439
  80%    451
  90%    484
  95%    520
  98%    544
  99%    604
 100%    754 (longest request)
```

最大リクエスト完了時間がケース1の46.7%にまで改善しました。
それでも0.7秒なので、もうちょっとなんとかなってほしいですね。

## ケース3: フルカラーPNGを事前生成して、そのデータを返す

エオルゼア時間は現実時間ベースなので、未来のエオルゼア時間を前もって求めることができます。
このことを利用して、エオルゼア時間の画像を先に作ってキャッシュしておいたものを送信する実装を行ってみました。

```text:et3.png
Document Path:          /api/et3.png
Document Length:        Variable

Concurrency Level:      200
Time taken for tests:   5.456 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      21366343 bytes
HTML transferred:       19916343 bytes
Requests per second:    1832.76 [#/sec] (mean)
Time per request:       109.125 [ms] (mean)
Time per request:       0.546 [ms] (mean, across all concurrent requests)
Transfer rate:          3824.15 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.8      1      13
Processing:     5  107  38.4    112     202
Waiting:        2  107  38.4    112     201
Total:         10  109  38.5    114     202

Percentage of the requests served within a certain time (ms)
  50%    114
  66%    128
  75%    138
  80%    144
  90%    157
  95%    165
  98%    173
  99%    179
 100%    202 (longest request)
```

あれ、なんかめっちゃいい。

## ケース4: モノクロPNGを事前生成して、そのデータを返す

ケース2と3の合わせ技も試してみましょう。

```text:et4.png
Document Path:          /api/et4.png
Document Length:        Variable

Concurrency Level:      200
Time taken for tests:   5.390 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      6099120 bytes
HTML transferred:       4649120 bytes
Requests per second:    1855.29 [#/sec] (mean)
Time per request:       107.800 [ms] (mean)
Time per request:       0.539 [ms] (mean, across all concurrent requests)
Transfer rate:          1105.04 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.0      1       8
Processing:    10  106  36.1    108     202
Waiting:        2  106  36.1    108     201
Total:         11  107  36.2    109     202

Percentage of the requests served within a certain time (ms)
  50%    109
  66%    123
  75%    134
  80%    140
  90%    152
  95%    164
  98%    179
  99%    190
 100%    202 (longest request)
```

あれっ、ケース3とほとんど差がないの？？？

# おわりに

Cisco Unified IP Phone Services Application、皆さんもぜひ作ってみてください。
~~まず実機を手に入れるところから~~

# おまけ: 今回の検証に使用したコード

```javascript:web.app
// ============================================================ #
//  Copyright (c) 2024 CIB-MC
//  Released under the MIT license
//  https://opensource.org/licenses/mit-license.php
// ============================================================ #

const express = require('express');
const app = express();
const createCanvas = require('canvas')

app.get('/api/et1.png', (req, res) => {
    let dt = new Date();
    let buffer = createEtPng(dt, true);
    res.set('content-type', 'image/png');
    res.end(buffer);
});

app.get('/api/et2.png', (req, res) => {
    let dt = new Date();
    let buffer = createEtPng(dt, false);
    res.set('content-type', 'image/png');
    res.end(buffer);
});

let cache_et3 = {};
let cache_et4 = {};

app.get('/api/et3.png', (req, res) => {
    let dt = new Date();
    let buffer = cache_et3['_' + Math.floor(dt.getTime() / 1000)];
    if (!buffer) {
            console.log('Cache mishit!')
            res.status(404).end();
            return;
    }
    res.set('content-type', 'image/png');
    res.end(buffer);
});

app.get('/api/et4.png', (req, res) => {
    let dt = new Date();
    let buffer = cache_et4['_' + Math.floor(dt.getTime() / 1000)];
    if (!buffer) {
            console.log('Cache mishit!')
            res.status(404).end();
            return;
    }
    res.set('content-type', 'image/png');
    res.end(buffer);
});

const CACHE_TTL = 20;
const cacheCreateStartup = () => {
    let dt = new Date();
    for (let i = 0; i < CACHE_TTL; i++) {
        dt.setSeconds(dt.getSeconds() + 1, 0);
        const cache_key = '_' + Math.floor(dt.getTime() / 1000);
        cache_et3[cache_key] = createEtPng(dt, true);
        cache_et4[cache_key] = createEtPng(dt, false);
        console.log(cache_key + " precreated.");
    }
    console.log("--> Cache precreate done!");
}

const cacheCreate = () => {
    let dt = new Date();
    dt.setSeconds(dt.getSeconds() + 10, 0);
    const cache_key = '_' + Math.floor(dt.getTime() / 1000);
    if (!(cache_key in cache_et3)) {
        cache_et3[cache_key] = createEtPng(dt, true);
        console.log('Cache ' + cache_key + ' created for et3.');
    }
    if (!(cache_key in cache_et4)) {
        cache_et4[cache_key] = createEtPng(dt, false);
        console.log('Cache ' + cache_key + ' created for et4.');
    }
}

const cachePurge = () => {
    let count_et3 = 0;
    let count_et4 = 0;
    let dt = new Date();
    let dt_ttl_over = dt.setSeconds(dt.getSeconds() - CACHE_TTL, 0);
    for(let key in cache_et3) {
        let key_ts = parseInt(key.replace('_', '')) * 1000;
        let key_dt = new Date(key_ts);
        if (key_dt < dt_ttl_over) {
            delete cache_et3[key];
            count_et3++;
        }
    }
    for(let key in cache_et4) {
        let key_ts = parseInt(key.replace('_', '')) * 1000;
        let key_dt = new Date(key_ts);
        if (key_dt < dt_ttl_over) {
            delete cache_et4[key];
            count_et4++;
        }
    }
    console.log('Purged ' + count_et3 + '&' + count_et4 + ' cache(s).')
}


class EorzeaDatetime {
        weekepoch = 0;
        constructor(datetime) {
                var dt = datetime ? datetime : new Date();
                var dt_jst = new Date(dt.toLocaleString({ timeZone: 'Asia/Tokyo' }))
                var dt_ws = new Date(dt_jst.getFullYear(), dt_jst.getMonth(), dt_jst.getDate() - dt_jst.getDay(), 0, 0, 0, 0);
                this.weekepoch = (dt_jst.getTime() * (1440 / 70)) - (dt_ws.getTime() * (1440 / 70));
        }
        getHours() {
                return Math.floor(this.weekepoch / 3600000) % 24;
        }
        getMinutes() {
                return Math.floor(this.weekepoch / 60000) % 60;
        }
        getSeconds() {
                return Math.floor(this.weekepoch / 1000) % 60;
        }
}

function appendZero(str, digits) {
    str = '' + str;
    while (str.length < digits) {
        str = "0" + str;
    }
    return str;
}

const createEtPng = (dt_arg, is_color) => {
    let dt = structuredClone(dt_arg);
    const canvas = createCanvas(320, 156);
    const ctx = canvas.getContext('2d', {pixelFormat: is_color ? 'RGB24' : 'A1'});
    ctx.fillStyle = is_color ? "#000" : 'rgba(0,0,0,0)';
    ctx.fillRect(0,0,320,156);

    dt.setMilliseconds(dt.getMilliseconds() + 500);
    let edt = new EorzeaDatetime(dt);
    
    ctx.fillStyle = is_color ? "#fff" : 'rgba(0,0,0,1)';
    ctx.textAlign = 'center';
    ctx.font = "normal 30px monospace";
    ctx.fillText('Eorzea Time', 160, 40);
    ctx.font = "bold 60px monospace";
    ctx.fillText(appendZero(edt.getHours(), 2) + ':' + appendZero(edt.getMinutes(),2), 160, 120);

    return canvas.toBuffer("image/png");
}

app.listen(3000, () => {
  cacheCreateStartup();
  setInterval(cachePurge, 1000 * 30);
  setInterval(cacheCreate, 250);
  console.log('Server listening on port 3000');
});
```