Renderの無料プランだと、Djangoがなぜ遅いのかログを見て調べてみた。
Renderniデプロイしたものは立ち上がりが遅いので確認してみてください。
https://ac-web2ren.onrender.com/の下に複数アプリがあるので、
どれか立ち上がっていれば、他のは速く立ち上がります。
ChatGptに聞いたりネットで調べた情報を自分なりに解釈してまとめました。
なので、思い込みや間違いがあることをご了承ください。
15分でスリープする件は、ここに書いてあります。
https://docs.render.com/free#free-web-services
Nginx＋Gunicorn＋Django
RenderのようなDjangoが動かせるサーバーの構成は
webサーバー＝Nginx（RenderでNginxを使っているかは分からない。）
アプリケーションサーバー＝gunicorn
から構成されているようです。
Djangoアプリケーションを本番環境で運用する際、通常はNginxとgunicornという2つの主要なコンポーネントを組み合わせて使用します。これらのコンポーネントは、Webサーバーとアプリケーションサーバーとしての役割を果たし、Djangoアプリケーションを高性能で安定した方法で提供します。以下に、Nginxとgunicornの関係を説明します：
- Nginx (Webサーバー):
- Nginxは高性能なWebサーバーソフトウェアで、HTTPリクエストの受け入れ、静的ファイルの配信、リバースプロキシ、負荷分散など、多くのWebサーバー機能を提供します。
- Nginxは一般に、クライアント（ブラウザやアプリケーション）からのHTTPリクエストを受け付け、それらのリクエストを適切なバックエンドサーバー（gunicornなどのアプリケーションサーバー）に転送する役割を担います。
- 静的ファイルの提供やSSL証明書の終端、URLルーティング、アクセス制御など、さまざまなWebサーバー関連の機能を処理します。
- gunicorn (アプリケーションサーバー):
- gunicorn（Green Unicorn）は、Pythonアプリケーションを実行するためのWSGIサーバーであり、HTTPリクエストを受け取り、Djangoアプリケーションを処理する役割を果たします。
- gunicornは高い並行性とパフォーマンスを提供し、複数のワーカープロセスを生成して多くのリクエストを同時に処理できるようにします。
- また、gunicornはWSGIインターフェースに準拠しており、Djangoアプリケーションとの間でスムーズに通信します。
Nginxとgunicornの組み合わせの一般的なフローは次のようになります：
- クライアントからのHTTPリクエストがNginxに届きます。
- Nginxはリクエストを受け取り、必要に応じて静的ファイルの提供などを行います。
- Nginxは、Djangoアプリケーションに対するリクエストをgunicornにプロキシ（転送）します。
- gunicornはリクエストを受け取り、Djangoアプリケーション内でビジネスロジックを実行し、レスポンスを生成します。
- gunicornはレスポンスをNginxに返し、Nginxはそれをクライアントに返します。
このように、Nginxとgunicornの組み合わせにより、静的ファイルの高効率な提供、リバースプロキシング、セキュリティ設定、負荷分散などの利点を享受しながら、Djangoアプリケーションのパフォーマンスと信頼性を向上させることができます。
起動コマンド
ローカル環境で動かすときはpython manage.py runserverを実行していますが。
Renderで動かすときpython manage.py runserverは使っていません。
（python manage.py runserverでも動きました。後述します。）
その代わりになるのがRenderのダッシュボードの
startCommand:で設定している
gunicorn プロジェクト名.wsgi:applicationになります。
python manage.py runserverとgunicornは何が違うのか？（個人的推察）
WSGIは以下がわかりやすいです。
参考：WSGIアプリケーションとは？WebフレームワークからWSGIサーバーまで – Make組ブログ (hirokiky.org)
【サンプル付き】WSGIとは?その役割やメリットをわかりやすく解説 (itc.tokyo)
runserverとの違いが気になるので
参考：runserver がどう動いているか実装をみる – そのあれ (hatenablog.jp)
gunicornと同じWSGIで動いてるっぽい。
多分違いはgunicornはwockerが複数できてリクエストを並列にさばけるのに対して
runserverのほうは1個しかさばけないのではないかと推測します。
前段のNginxでもwockerがありますが、
Nginxはリクエストを振り分けるところで最終的なレスポンスを作りません。
なのでgunicornはレスポンスを作り出す処理もwockerによって
複数作り出せるのだと思います。
また、gunicornとDjangoの関係は、
Djangoの処理はgunicornのwockerとしてレスポスまで作り出せるのではないかと推察します。
そうしないと、またDjango（アプリケーションサーバー）でwockerのように複数処理できるようにしなければなりませんが、そういう情報は見当たらないし、
下で実際にrunserverで動かしたログにwockerはないのでそう考えました。
なので本番ではgunicornを使うのが一般的みたい。
実際のログ
何のログかというとアクセスログや起動時のログなどいろいろ記録されています。
以下は、このアプリhttps://ac-web2ren.onrender.com/mtaj/のログの一部です。
Oct 25 12:19:43 PM 10.209.21.153 - - [25/Oct/2023:12:19:43 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 12:19:48 PM 10.209.21.153 - - [25/Oct/2023:12:19:48 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 12:19:53 PM 10.209.21.153 - - [25/Oct/2023:12:19:53 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 12:19:58 PM 10.209.21.153 - - [25/Oct/2023:12:19:58 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 12:19:59 PM [2023-10-25 12:19:59 +0900] [54] [INFO] Handling signal: term
Oct 25 12:19:59 PM [2023-10-25 12:19:59 +0900] [56] [INFO] Worker exiting (pid: 56)
Oct 25 12:19:59 PM [2023-10-25 12:19:59 +0900] [59] [INFO] Worker exiting (pid: 59)
Oct 25 12:19:59 PM [2023-10-25 12:19:59 +0900] [57] [INFO] Worker exiting (pid: 57)
Oct 25 12:19:59 PM [2023-10-25 12:19:59 +0900] [58] [INFO] Worker exiting (pid: 58)
Oct 25 12:20:07 PM [2023-10-25 12:20:07 +0900] [54] [INFO] Shutting down: Master
↑↑↑↑↑ここで停止↑↑↑↑↑↑↑↑↑
↓↓↓↓↓ここで再開↓↓↓↓↓↓↓↓↓
Oct 25 12:59:26 PM ==> Using Node version 14.17.0 (default)
Oct 25 12:59:26 PM ==> Docs on specifying a Node version: https://render.com/docs/node-version
Oct 25 12:59:34 PM ==> Running 'gunicorn access_counter.wsgi:application'
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [54] [INFO] Starting gunicorn 21.2.0
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [54] [INFO] Listening at: http://0.0.0.0:10000 (54)
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [54] [INFO] Using worker: sync
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [56] [INFO] Booting worker with pid: 56
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [57] [INFO] Booting worker with pid: 57
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [58] [INFO] Booting worker with pid: 58
Oct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [59] [INFO] Booting worker with pid: 59
Oct 25 12:59:59 PM 10.209.23.111 - - [25/Oct/2023:12:59:59 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:04 PM 10.209.23.111 - - [25/Oct/2023:13:00:04 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:12 PM 10.209.23.111 - - [25/Oct/2023:13:00:12 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:13 PM 10.209.23.111 - - [25/Oct/2023:13:00:13 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:13 PM 10.209.23.111 - - [25/Oct/2023:13:00:13 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:13 PM 127.0.0.1 - - [25/Oct/2023:13:00:13 +0900] "GET /mtaj HTTP/1.1" 301 0 "https://kikuichige.com/10919/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/118.0.0.0 Safari/537.36 Edg/118.0.2088.61"
Oct 25 01:00:14 PM 127.0.0.1 - - [25/Oct/2023:13:00:14 +0900] "GET /mtaj/ HTTP/1.1" 200 6293 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/118.0.0.0 Safari/537.36 Edg/118.0.2088.61"
Oct 25 01:00:17 PM 127.0.0.1 - - [25/Oct/2023:13:00:17 +0900] "GET /mtaj/plot/ HTTP/1.1" 200 15059 "https://ac-web2ren.onrender.com/mtaj/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/118.0.0.0 Safari/537.36 Edg/118.0.2088.61"
Oct 25 01:00:17 PM 127.0.0.1 - - [25/Oct/2023:13:00:17 +0900] "GET /favicon.ico HTTP/1.1" 404 179 "https://ac-web2ren.onrender.com/mtaj/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/118.0.0.0 Safari/537.36 Edg/118.0.2088.61"
Oct 25 01:00:23 PM 10.209.23.111 - - [25/Oct/2023:13:00:23 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:25 PM 10.209.23.111 - - [25/Oct/2023:13:00:25 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
Oct 25 01:00:28 PM 10.209.23.111 - - [25/Oct/2023:13:00:28 +0900] "GET / HTTP/1.1" 200 553 "-" "Render/1.0"
目次へhealth chhek
5秒おきに同じようなログが残っているので、その中で赤線部分をChatGptに聞いた。
ChatGptに聞いた答えの中で注目するところは
8，のユーザーエージェント情報で"Render/1.0"になっている点。たぶんhealth chekのアクセスではないかと思います。
ただ2，リモートクライアントのIPアドレスが
再開前は10.209.21.153で再開後が10.209.23.111になっているのは不思議です。
提供されたログエントリは、HTTPアクセスログの一部であり、クライアントからのHTTP GETリクエストに関する情報を含んでいます。以下はこのログエントリの各要素についての解説です：
- “Oct 25 12:19:58 PM”: この部分は、ログエントリが生成された日付と時刻を示しています。具体的には、10月25日の午後12時19分58秒（+0900はタイムゾーン情報）にログが記録されたことを示しています。
- “10.209.21.153”: これはリモートクライアントのIPアドレスです。このログエントリはIPアドレス “10.209.21.153” からのリクエストを示しています。このIPアドレスはリモートクライアントを表します。
- “[25/Oct/2023:12:19:58 +0900]”: この部分は、HTTPリクエストが発生した日付と時刻を示しています。具体的には、2023年10月25日の午後12時19分58秒（+0900はタイムゾーン情報）にリクエストが行われたことを示しています。
"GET / HTTP/1.1": これはHTTPメソッド、リクエストされたリソースのパス、および使用されたHTTPバージョンを示しています。
- HTTPメソッド: “GET” は、リソースの取得をリクエストすることを意味します。
- リソースのパス: “/” は、ルートパスを表し、ウェブサイトのホームページをリクエストしています。
- HTTPバージョン: “HTTP/1.1” は、HTTPプロトコルのバージョンを示します。
5，”200″: これはHTTPステータスコードで、リクエストが成功したことを示す “200 OK” を表しています。つまり、リソースが正常に取得されました。
6，”553″: これはレスポンスのサイズを示しています。つまり、サーバーからクライアントに送信されたレスポンスのバイト数です。
7，"-": この部分はリファラ（リファラル）情報を示しており、クライアントがこのリクエストをどのURLから送信したかを示すものです。この場合、リファラ情報は含まれていません。
8，"Render/1.0": この部分はユーザーエージェント情報で、クライアントが使用しているブラウザやクライアントアプリケーションを示しています。
このログエントリは、クライアントからのHTTP GETリクエストが成功し、正常なレスポンスが提供されたことを示しています。
そこでHealth checkをオフにしてみます。
settingsのHealth＆AlertsでHealth Check Pathに/が入っていたのですが、
これを消してSave Changeすると、５秒おきの"Render/1.0"のアクセスがなくなりました。
やはりHealth chekのようです。ログは見やすくなりますが、
これをはずしたからといって、スピードは変わらないのでもとに戻しておきます。
複数のクライアントのHTTPリクエストをどうやって処理するのか？
またクライアントのアクセス部分（赤太字）のIPアドレスが127.0.0.1 （ローカルループバックアドレス）になっていて、自分のIPということですが分かりにくいです。
とにかくクライアントのIPアドレスはログには出ていない部分で、
gunicornに渡されているはずです。
Oct 25 01:00:13 PM 127.0.0.1 - - [25/Oct/2023:13:00:13 +0900] "GET /mtaj HTTP/1.1" 301 0 "https://kikuichige.com/10919/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64)
目次へworker
workerは
「gunicornは、Pythonアプリケーションを実行する際に、並行してリクエストを処理するために複数のワーカー（workers）を生成することができます。ワーカーは、クライアントからのリクエストを受け取り、それに対するレスポンスを生成する役割を果たします。」（ChatGpt談）
ということなのでDjangoの同じプロジェクトを複数同時に動かして、
クライアントからのリクエストがたくさんきても処理できるようにしているものと思われる。
ログの中のOct 25 12:59:39 PM [2023-10-25 12:59:39 +0900] [56] [INFO] Booting worker with pid: 56の部分もChatGptに聞くと
[YYYY-MM-DD HH:MM:SS +0000] [PID:ワーカープロセスのPID] [INFO] worker with pid: ワーカープロセスのPID
ということなので、ログ全体で確認するとワーカープロセスのPIDが56、57、58、59と4つある。
よって4つプロジェクトが動いているものと思われる。
ただ複数のHTTPリクエストを同時に処理する場合
gunicornでは、どのクライアントからのHTTPリクエストを
どのwokerが処理しているのか管理していないと正しく動作しないはずです。
例えば
クライアントAのアクセスに対する処理をworker with pid: 56にやらせ、
クライアントBのアクセスに対する処理をworker with pid: 57にやらせた場合。
どこかでこの割り振りを管理する必要があります。
そうしないとworker56のレスポンスがクライアントBに返されたりしたら大変です。
その辺の仕組みは、ちょっと分かりません。
もうひとつ疑問が、アプリによってworkerの数が違いました。
１個のものと４個のものがあります。
調べたら
workerの数はEnvironmentのEnvironment Variablesで
WEB_CONCURRENCY 4としていたからでした。（yamlでデプロイものは設定していた）
1にしたらwokerが1個になりました。
別にアクセスされる数が、ほぼないのでwokerの数を減らしても問題にはならないでしょう。
むしろwokerの数は少ない方がメモリ消費が少なくなるのと、
立ち上がりも少し速くなるかもしれません。
Nginx、gunicorn、woker、リバースプロキシなどをちょっと勉強したほうがいいなと思いました。
参考：リバースプロキシの設定、Gunicorn + Flask + nginx で Python の Web アプリ入門
Gunicornってなに？
VPSで、関連事項をいろいろ実験してみた。↓
シャットダウン
クライアントが最後にアクセスしてから15分後gunicornをシャットダウンしているようです。
提供されたログは、gunicornのシャットダウンプロセスに関連しています。以下に各行の解説を提供します：
- “Handling signal: term”: この行は、gunicornがSIGTERM（終了シグナル）を受信していることを示しています。SIGTERMは通常、プロセスに対して優雅なシャットダウンのリクエストを送るために使用されます。プロセスはこれを受信すると、実行中の処理を完了して終了することが期待されます。
- “Worker exiting (pid: 56)”: これらの行は、各ワーカープロセスが終了していることを示しています。各行には、ワーカープロセスのPIDが含まれており、それぞれのプロセスが終了したことが報告されています。ワーカープロセスは、gunicornが処理したリクエストを完了し、シャットダウンするために終了しています。
- “Shutting down: Master”: この行は、gunicornのマスタープロセスがシャットダウンプロセスに入っていることを示しています。マスタープロセスはgunicornのコントロールを担当し、ワーカープロセスの生成や終了を監視します。マスタープロセスがシャットダウンされると、gunicornは完全に停止します。
これらのログは、gunicornの正常なシャットダウンプロセスを示しています。SIGTERMを受信した後、各ワーカープロセスはリクエストの処理を完了し、順次終了しています。最終的に、マスタープロセスもシャットダウンされ、gunicornの実行が終了します。このようなプロセスは、アプリケーションやサービスを安全かつ制御可能にシャットダウンするのに役立ちます。
gunicorn起動
クライアントがアクセスすると、gunicornが起動されます。
提供されたログは、gunicornが起動し、ワーカープロセスを生成してPythonアプリケーションを実行する過程を示しています。以下にログの各行について解説します：
- “Using Node version 14.17.0 (default)”: この行は、Node.jsのバージョンが14.17.0であることを示しています。Node.jsはJavaScriptランタイムであり、この情報はおそらくアプリケーションに必要なNode.jsのバージョンを示すものです。
- “Docs on specifying a Node version: https://render.com/docs/node-version”: この行は、Node.jsバージョンを指定する方法に関するドキュメントへのリンクを提供しています。これはNode.jsのバージョンを設定または変更する方法に関する情報を提供しています。
- “Running ‘gunicorn access_counter.wsgi:application'”: この行は、gunicornを使用してPythonアプリケーション（”access_counter.wsgi:application”）を実行していることを示しています。これはgunicornコマンドを介してアプリケーションが起動されています。
- “[2023-10-25 12:59:39 +0900] [54] [INFO] Starting gunicorn 21.2.0”: この行は、gunicornのバージョン情報を含むgunicornの起動情報を示しています。
- “[2023-10-25 12:59:39 +0900] [54] [INFO] Listening at: http://0.0.0.0:10000 (54)”: この行は、gunicornがリスンするホストとポートを示しています。具体的には、0.0.0.0のすべてのネットワークインターフェース上でポート10000でリクエストを受け入れることを示しています。最後の “(54)” は、gunicornのマスタープロセスのPIDを示しています。
- “[2023-10-25 12:59:39 +0900] [54] [INFO] Using worker: sync”: この行は、gunicornが同期ワーカー（”sync”）を使用していることを示しています。同期ワーカーはリクエストを順番に処理する方式です。
- “[2023-10-25 12:59:39 +0900] [56] [INFO] Booting worker with pid: 56”: これらの行は、ワーカープロセスが生成されていることを示しています。各行は、ワーカープロセスのPIDと、そのプロセスが起動したことを報告しています。新しいリクエストを処理するために複数のワーカープロセスが起動されていることがわかります。
これらのログは、gunicornの起動とワーカープロセスの生成を監視し、アプリケーションの実行状態を確認するのに役立ちます。特に、各ワーカープロセスのPIDは、デバッグやトラブルシューティングの際に特定のプロセスを追跡するのに役立ちます。
遅い原因
クライアントがアクセスしてRenderが反応しだしてからDjangoにGetとアクセス先のurl情報が伝わってレスポンスするまで、このログの場合01:00:13-12:59:26 ＝47秒かかっています。
Oct 25 12:59:26 PM ==> Using Node version 14.17.0 (default)
略
Oct 25 01:00:13 PM 127.0.0.1 - - [25/Oct/2023:13:00:13 +0900] "GET /mtaj HTTP/1.1" 301 0 "https://kikuichige.com/10919/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) 恐らくHerokuやRailwayや多分Render有料も、
gunicornをシャットダウンすることはないから速いのだと思います。
Start Commandをpython manage.py runserverに変更してみた
DashboardのsttingsのStart Commandをgunicorn （wsgi.pyのあるディレクトリ）.wsgi:application
→python manage.py runserver 0.0.0.0:8000
というようにgunicornを使わずにローカールで使っているコマンドに変えてみた。
render.yamlに書いた
startCommand: 'gunicorn （wsgi.pyのあるディレクトリ）.wsgi:application'はそのままでも
settingsで設定したほうが優先されるのかも。
しかし立ち上がりが遅いのは変わらなかった。
以下、実際のログです。==> Using Node version 14.17.0 (default)
==> Docs on specifying a Node version: https://render.com/docs/node-version
==> Using Bun version (default)
==> Docs on specifying a bun version: https://render.com/docs/bun-version
==> Running 'python manage.py runserver 0.0.0.0:8000'
[18/Apr/2024 14:27:13] "GET / HTTP/1.1" 200 10912
[18/Apr/2024 14:27:13] "GET /api/d_rakuten_app/?search= HTTP/1.1" 200 8339
[18/Apr/2024 14:27:14] "GET /favicon.ico HTTP/1.1" 404 17915分おきのcronで自動アクセス
15分でスリープ（https://docs.render.com/free#free-web-services）するので、
その前に定期的にアクセスすれば、ずっとスリープしないはずです。
なので毎時00、15、30、45分に定期的にアクセスしてみます。
シン・クラウド for Free（無料）のcron↓でやってみたらできました。
ただ1人750/month（750ｈ/24h=31.25日）の制限があります。
なので1個のurlで1ゕ月はできそうですが、2個以上のURLは無理そうです。
追加料金は発生しないと思いますが、
これから（2024/4/7）15分おきにcronでアクセスしてみます。
この方法で運用してるアプリイチゲブログ掲示板（csvをシン・クラウド for Free保存）
まとめ
（追記：python manage.py runserverでも同じだった。）
Djangoをローカル環境でpython manage.py runserverで実行しているのとは違い、
gunicornで実行している。
このgunicornが起動してから反応しだすまでの時間が長い。
一度起動するとローカル環境と同じくらい速いレスポンスになる。
しかしgunicornが１５分経つとシャットダウンしてしまうので、
１５分後に、またアクセスするとgunicornの起動から動作するので遅い。
もう少し掘り下げるため以下を実行しました。
目次へ
イチゲをOFUSEで応援する(御質問でもOKです）Vプリカでのお支払いがおすすめです。
MENTAやってます（ichige）
コメント