A large number of "body not consumed" appeared in the stress test using jmeter

Questions and Help
#1

Hi, I wrote a demo and ran a stress test using jmeter. I encountered some problems:

(sanic) PS D:\\hello_world> & C:/Users/wakeya/Miniconda3/envs/sanic/python.exe d:/hello_world/server.py
[2022-12-07 11:55:01 +0800] [65420] [WARNING] Directory d:\my_apps_sanic could not be located
[2022-12-07 11:55:01 +0800] [65420] [INFO] 
  ┌───────────────────────────────────────────────────────────────────────────────────┐
  │                                   Sanic v22.9.1                                   │
  │                         Goin' Fast @ http://127.0.0.1:8000                        │
  ├───────────────────────┬───────────────────────────────────────────────────────────┤
  │                       │        mode: production, goin' fast w/ 16 workers         │
  │     ▄███ █████ ██     │      server: sanic, HTTP/1.1                              │
  │    ██                 │      python: 3.7.6                                        │
  │     ▀███████ ███▄     │    platform: Windows-10-10.0.22621-SP0                    │
  │                 ██    │ auto-reload: enabled, d:\my_apps_sanic │
  │    ████ ████████▀     │    packages: sanic-routing==22.8.0                        │
  │                       │                                                           │
  │ Build Fast. Run Fast. │                                                           │
  └───────────────────────┴───────────────────────────────────────────────────────────┘

[2022-12-07 11:55:01 +0800] [65420] [WARNING] Sanic is running in PRODUCTION mode. Consider using '--debug' or '--dev' while actively developing your application.
[2022-12-07 11:55:02 +0800] [4300] [INFO] Starting worker [4300]
[2022-12-07 11:55:02 +0800] [15616] [INFO] Starting worker [15616]
[2022-12-07 11:55:02 +0800] [39508] [INFO] Starting worker [39508]
[2022-12-07 11:55:02 +0800] [63120] [INFO] Starting worker [63120]
[2022-12-07 11:55:02 +0800] [38780] [INFO] Starting worker [38780]
[2022-12-07 11:55:02 +0800] [44000] [INFO] Starting worker [44000]
[2022-12-07 11:55:02 +0800] [45388] [INFO] Starting worker [45388]
[2022-12-07 11:55:02 +0800] [21024] [INFO] Starting worker [21024]
[2022-12-07 11:55:02 +0800] [53084] [INFO] Starting worker [53084]
[2022-12-07 11:55:02 +0800] [31808] [INFO] Starting worker [31808]
[2022-12-07 11:55:02 +0800] [72124] [INFO] Starting worker [72124]
[2022-12-07 11:55:02 +0800] [22680] [INFO] Starting worker [22680]
[2022-12-07 11:55:02 +0800] [50224] [INFO] Starting worker [50224]
[2022-12-07 11:55:02 +0800] [44056] [INFO] Starting worker [44056]
[2022-12-07 11:55:02 +0800] [23700] [INFO] Starting worker [23700]
[2022-12-07 11:55:02 +0800] [30104] [INFO] Starting worker [30104]
[2022-12-07 13:06:11 +0800] [65204] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [32552] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [42552] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [41216] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [50232] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [42136] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [65776] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [32120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [62500] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [27416] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [50232] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [35120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [65204] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [62796] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [42552] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [42552] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [32120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [35120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [24544] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [49452] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [65776] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [49452] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [35120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [35120] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [23404] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
[2022-12-07 13:06:11 +0800] [24544] [ERROR] <Request: GET /my_api/test/v1> body not consumed.
......

There are many more “[2022-12-07 13:06:11 +0800] [24544] [ERROR] <Request: GET /my_api/test/v1> body not consumed.”. But it’s normal if the request is made individually.

My project structure：

sanic-demo-01
sanic-demo-011602×1173 178 KB

hello_world->server.py:

# __Date__    : 2022/12/6 15:05
# __Author__  : wakeya
# Description : sanic Entry file
import os
import sys
from sanic import Sanic
from my_apps_sanic import api_sanic


BASE_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__)))
sys.path.insert(0, os.path.join(BASE_DIR, 'hello_world'))
SANIC_RELOAD_DIR = [
    BASE_DIR + os.sep + "my_apps_sanic"
]
app = Sanic("hello_world")
app.config["KEEP_ALIVE_TIMEOUT"] = 300
app.blueprint(api_sanic)


if __name__ == '__main__':
    app.run(
        host='127.0.0.1',
        port=8000,
        fast=True,
        auto_reload=True,
        reload_dir=SANIC_RELOAD_DIR,
        access_log=False
    )

hello_world->my_apps_sanic->init.py :

# __Date__    : 2022/12/6 15:05
# __Author__  : wakeya
# Description : all apps api
from sanic import Blueprint
from .my_demo import api_test

api_sanic = Blueprint.group(
    api_test,
    url_prefix='/my_api'
)

hello_world->my_apps_sanic->my_demo->init.py :

# __Date__    : 2022/12/6 15:17
# __Author__  : wakeya
# Description : my_demo app route


from sanic import Blueprint
from .views import bp_my_demo

api_test = Blueprint.group(
    bp_my_demo,
    url_prefix='/test'
)

hello_world->my_apps_sanic->my_demo->views.py :

# __Date__    : 2022/12/6 15:17
# __Author__  : wakeya
# Description : my_domo app
import asyncio
from sanic import response, Blueprint


bp_my_demo = Blueprint("test")


@bp_my_demo.get("/")
async def hello_world(request):
    await asyncio.sleep(0.1)
    return response.text("value")


@bp_my_demo.get("/sanic")
async def hello_world2(request):
    await asyncio.sleep(0.1)
    return response.json({
        "code": 0,
        "data": {
            "id": "923554e2-7e15-4390-9330-864fedbd2604",
        },
        "msg": "Hello, world 3.  ",
    })


@bp_my_demo.get("/v1")
async def v1(request):
    await asyncio.sleep(0.2)
    return response.json({
        "code": 0,
        "data": {
            "id": "923554e2-7e15-4390-9330-864fedbd2604",
        },
        "msg": "ok",
    })

The following local apis are available:

http://127.0.0.1:8000/my_api/test/
http://127.0.0.1:8000/my_api/test/sanic
http://127.0.0.1:8000/my_api/test/v1

My jmeter configuration is as follows:

  • Thread Group
Number of Threads(users): 100
Ramp-up period(seconds): 1
Loop Count: 5
  • HTTP Request
http://127.0.0.1:8000/my_api/test/v1

Then when I tested it, I saw a lot of “body not consumed.”

Why is that?

Thank you in advance.

#2

My jmeter configuration 01 is as follows:

sanic-demo-02
sanic-demo-023048×1669 150 KB

#3

My jmeter configuration 02 is as follows:

sanic-demo-03
sanic-demo-033048×1669 156 KB

#4

My jmeter configuration 03 is as follows:

sanic-demo-04
sanic-demo-043048×1669 134 KB

#5

My jmeter results is as follows:

sanic-demo-05
sanic-demo-053839×1978 388 KB

#6

As discussed in Discord, this happens when a body is sent to an endpoint that is not expecting it. On endpoints that are not supposed to receive body, Sanic stops reading from the buffer. You can force it to consume, or do so manually if needed.

1 Like
#8

Thank you very much again. :smiling_face_with_three_hearts: