Runpod serverless overhead/slow

teddycatsdomino · 2024-08-11T23:37:28.158Z

I have a handler that is apparently running very fast, but my requests are not. I'm hoping to process video frames. I know this is an unconventional use case, but it appears that it is working reasonably well with this one exception: ``` 2024-08-11T23:25:55.468886839Z INFO: 127.0.0.1:40312 - "POST /process_frame HTTP/1.1" 200 OK 2024-08-11T23:25:55.469954721Z handler.py :61 2024-08-11 23:25:55,469 Local server request completed in 0.079 seconds 2024-08-11T23:25:55.470257231Z handler.py :70 2024-08-11 23:25:55,470 Handler completed in 0.080 seconds ``` What we're actually seeing are not fast responses, but responses that take at least a second, and often longer. The runpod dashboard claims that this is execution time, but the worker logs disagree. Request ID Delay Time Execution Time sync-61d689e6-502e... 0.18s 1.28s What's going on here? Is there anything we can do? I'll post my handler code in the next message.

T

teddycatsdominoOP•8/11/24, 11:38 PM

My handler code looks like this:

def is_server_running():
    for process in psutil.process_iter(['name', 'cmdline']):
        if process.info['name'] == 'python3' and 'server.py' in process.info['cmdline']:
            return True
    return False

def start_server():
    if is_server_running():
        print("Server is already running.")
        return None
    
    server_process = subprocess.Popen([sys.executable, "server.py"])
    if not is_server_ready():
        stop_server(server_process)
        raise Exception("Server failed to start within the allocated time")
    return server_process

def handler(event):
    start_time = time.time()
    logger.info("Handler started")
    try:
        job_input = event["input"]
        
        if "frame" not in job_input:
            logger.error("No frame data provided")
            return {"error": "No frame data provided"}

        logger.info("Sending frame to local server")
        request_start = time.time()
        # Send the frame to the local server for processing
        response = requests.post("http://localhost:8080/process_frame", json={"frame": job_input["frame"]})
        request_end = time.time()
        logger.info(f"Local server request completed in {request_end - request_start:.3f} seconds")

        result = response.json()

        if "error" in result:
            logger.error(f"Error from local server: {result['error']}")
            return {"error": result["error"]}

        end_time = time.time()
        logger.info(f"Handler completed in {end_time - start_time:.3f} seconds")
        return {"processed_frame": result["processed_frame"]}

if __name__ == "__main__":
    start_server()
    runpod.serverless.start({"handler": handler})

def is_server_running():
    for process in psutil.process_iter(['name', 'cmdline']):
        if process.info['name'] == 'python3' and 'server.py' in process.info['cmdline']:
            return True
    return False

def start_server():
    if is_server_running():
        print("Server is already running.")
        return None
    
    server_process = subprocess.Popen([sys.executable, "server.py"])
    if not is_server_ready():
        stop_server(server_process)
        raise Exception("Server failed to start within the allocated time")
    return server_process

def handler(event):
    start_time = time.time()
    logger.info("Handler started")
    try:
        job_input = event["input"]
        
        if "frame" not in job_input:
            logger.error("No frame data provided")
            return {"error": "No frame data provided"}

        logger.info("Sending frame to local server")
        request_start = time.time()
        # Send the frame to the local server for processing
        response = requests.post("http://localhost:8080/process_frame", json={"frame": job_input["frame"]})
        request_end = time.time()
        logger.info(f"Local server request completed in {request_end - request_start:.3f} seconds")

        result = response.json()

        if "error" in result:
            logger.error(f"Error from local server: {result['error']}")
            return {"error": result["error"]}

        end_time = time.time()
        logger.info(f"Handler completed in {end_time - start_time:.3f} seconds")
        return {"processed_frame": result["processed_frame"]}

if __name__ == "__main__":
    start_server()
    runpod.serverless.start({"handler": handler})

def is_server_running():
    for process in psutil.process_iter(['name', 'cmdline']):
        if process.info['name'] == 'python3' and 'server.py' in process.info['cmdline']:
            return True
    return False

def start_server():
    if is_server_running():
        print("Server is already running.")
        return None
    
    server_process = subprocess.Popen([sys.executable, "server.py"])
    if not is_server_ready():
        stop_server(server_process)
        raise Exception("Server failed to start within the allocated time")
    return server_process

def handler(event):
    start_time = time.time()
    logger.info("Handler started")
    try:
        job_input = event["input"]
        
        if "frame" not in job_input:
            logger.error("No frame data provided")
            return {"error": "No frame data provided"}

        logger.info("Sending frame to local server")
        request_start = time.time()
        # Send the frame to the local server for processing
        response = requests.post("http://localhost:8080/process_frame", json={"frame": job_input["frame"]})
        request_end = time.time()
        logger.info(f"Local server request completed in {request_end - request_start:.3f} seconds")

        result = response.json()

        if "error" in result:
            logger.error(f"Error from local server: {result['error']}")
            return {"error": result["error"]}

        end_time = time.time()
        logger.info(f"Handler completed in {end_time - start_time:.3f} seconds")
        return {"processed_frame": result["processed_frame"]}

if __name__ == "__main__":
    start_server()
    runpod.serverless.start({"handler": handler})

def is_server_running():
    for process in psutil.process_iter(['name', 'cmdline']):
        if process.info['name'] == 'python3' and 'server.py' in process.info['cmdline']:
            return True
    return False

def start_server():
    if is_server_running():
        print("Server is already running.")
        return None
    
    server_process = subprocess.Popen([sys.executable, "server.py"])
    if not is_server_ready():
        stop_server(server_process)
        raise Exception("Server failed to start within the allocated time")
    return server_process

def handler(event):
    start_time = time.time()
    logger.info("Handler started")
    try:
        job_input = event["input"]
        
        if "frame" not in job_input:
            logger.error("No frame data provided")
            return {"error": "No frame data provided"}

        logger.info("Sending frame to local server")
        request_start = time.time()
        # Send the frame to the local server for processing
        response = requests.post("http://localhost:8080/process_frame", json={"frame": job_input["frame"]})
        request_end = time.time()
        logger.info(f"Local server request completed in {request_end - request_start:.3f} seconds")

        result = response.json()

        if "error" in result:
            logger.error(f"Error from local server: {result['error']}")
            return {"error": result["error"]}

        end_time = time.time()
        logger.info(f"Handler completed in {end_time - start_time:.3f} seconds")
        return {"processed_frame": result["processed_frame"]}

if __name__ == "__main__":
    start_server()
    runpod.serverless.start({"handler": handler})

I've removed bits and pieces in order for the message to fit, but the important code remains.

T

teddycatsdominoOP•8/11/24, 11:39 PM

I was also wondering if there's some way to use streaming for this, but it doesn't seem like it since we can only stream responses, we cannot stream data to the server, unless I'm misunderstanding something! I'd really love to spin up a worker per-user and let them connect via websockets but I'm not sure if there's a way to do anything like that.

E

Encyrption•8/11/24, 11:40 PM

What is running http://localhost:8080/process_frame?

T

teddycatsdominoOP•8/11/24, 11:41 PM

A process that actually processes the video frame and returns data to send to the user. We could probably fold it into the handler, but profiling shows that it takes a small fraction of a second to return.

E

Encyrption•8/11/24, 11:41 PM

You're handler looks fine to me... likely your dealy comes from process_frame

T

teddycatsdominoOP•8/11/24, 11:42 PM

It's running this:
https://neuralpanda.ai/elonify

Neural Panda

Make magic with video.

T

teddycatsdominoOP•8/11/24, 11:43 PM

Unless I'm misunderstanding my logging, it's very fast:
logger.info(f"Handler completed in {end_time - start_time:.3f} seconds")

2024-08-11T23:43:21.230260058Z handler.py          :48   2024-08-11 23:43:21,230 Handler started
2024-08-11T23:43:21.230512959Z handler.py          :56   2024-08-11 23:43:21,230 Sending frame to local server
2024-08-11T23:43:21.318790389Z INFO:     127.0.0.1:50212 - "POST /process_frame HTTP/1.1" 200 OK
2024-08-11T23:43:21.319975282Z handler.py          :61   2024-08-11 23:43:21,319 Local server request completed in 0.089 seconds
2024-08-11T23:43:21.320171923Z handler.py          :70   2024-08-11 23:43:21,320 Handler completed in 0.090 seconds

2024-08-11T23:43:21.230260058Z handler.py          :48   2024-08-11 23:43:21,230 Handler started
2024-08-11T23:43:21.230512959Z handler.py          :56   2024-08-11 23:43:21,230 Sending frame to local server
2024-08-11T23:43:21.318790389Z INFO:     127.0.0.1:50212 - "POST /process_frame HTTP/1.1" 200 OK
2024-08-11T23:43:21.319975282Z handler.py          :61   2024-08-11 23:43:21,319 Local server request completed in 0.089 seconds
2024-08-11T23:43:21.320171923Z handler.py          :70   2024-08-11 23:43:21,320 Handler completed in 0.090 seconds

2024-08-11T23:43:21.230260058Z handler.py          :48   2024-08-11 23:43:21,230 Handler started
2024-08-11T23:43:21.230512959Z handler.py          :56   2024-08-11 23:43:21,230 Sending frame to local server
2024-08-11T23:43:21.318790389Z INFO:     127.0.0.1:50212 - "POST /process_frame HTTP/1.1" 200 OK
2024-08-11T23:43:21.319975282Z handler.py          :61   2024-08-11 23:43:21,319 Local server request completed in 0.089 seconds
2024-08-11T23:43:21.320171923Z handler.py          :70   2024-08-11 23:43:21,320 Handler completed in 0.090 seconds

2024-08-11T23:43:21.230260058Z handler.py          :48   2024-08-11 23:43:21,230 Handler started
2024-08-11T23:43:21.230512959Z handler.py          :56   2024-08-11 23:43:21,230 Sending frame to local server
2024-08-11T23:43:21.318790389Z INFO:     127.0.0.1:50212 - "POST /process_frame HTTP/1.1" 200 OK
2024-08-11T23:43:21.319975282Z handler.py          :61   2024-08-11 23:43:21,319 Local server request completed in 0.089 seconds
2024-08-11T23:43:21.320171923Z handler.py          :70   2024-08-11 23:43:21,320 Handler completed in 0.090 seconds

This implies that it posted to the process_frame endpoint and received a response and is sending data back in 0.09 seconds right?

T

teddycatsdominoOP•8/11/24, 11:43 PM

Also, thank you so much for responding so quickly!

E

Encyrption•8/11/24, 11:44 PM

Are you running locally?

T

teddycatsdominoOP•8/11/24, 11:44 PM

Yes

T

teddycatsdominoOP•8/11/24, 11:44 PM

If you mean is the process_frame endpoint running locally.

E

Encyrption•8/11/24, 11:44 PM

are you doing a docker run each time?

T

teddycatsdominoOP•8/11/24, 11:44 PM

I have tested this both locally and deployed. The stats I've shown you are from the deployed version.

T

teddycatsdominoOP•8/11/24, 11:44 PM

And no, it's a simple FastAPI endpoint (process_frame is)

E

Encyrption•8/11/24, 11:45 PM

So from above the handler completes in 0.090 seconds. Is that not fast enough for you?

T

teddycatsdominoOP•8/11/24, 11:46 PM

Oh it is, but I don't get data that fast.

T

teddycatsdominoOP•8/11/24, 11:46 PM

The execution time from Runpod shows as 1.5 seconds+

T

teddycatsdominoOP•8/11/24, 11:46 PM

That's what's confusing me.

E

Encyrption•8/11/24, 11:47 PM

How many active, max workers do you have set. Have you enabled Flashboot?

T

teddycatsdominoOP•8/11/24, 11:47 PM

This is with an active worker. Just one that I'm using for testing.

T

teddycatsdominoOP•8/11/24, 11:47 PM

10 max, one active right now.

E

Encyrption•8/11/24, 11:48 PM

Are you doing synch or async RUN call?

T

teddycatsdominoOP•8/11/24, 11:48 PM

sync

E

Encyrption•8/11/24, 11:49 PM

With Sync you should get a response from the handler as soon as it finishes.... what is your experience?

T

teddycatsdominoOP•8/11/24, 11:50 PM

Well, I don't know where the delay is, but it takes 2-3 seconds to get a response from Runpod even though my handler says its' finishing processing in 0.09 seconds.

T

teddycatsdominoOP•8/11/24, 11:50 PM

And runpod's dashboard says the execution time is 1.5 seconds even though the handler disagrees.

T

teddycatsdominoOP•8/11/24, 11:50 PM

It's this delay that I'm trying to understand.

J

Jason•8/11/24, 11:54 PM

You should use pods instead or a worker with ws

E

Encyrption•8/11/24, 11:55 PM

With synchronous your client connects to the wireless worker, and waits for it to respond. With an active worker it should be booted up and waiting for your API call. So, when you connect your response should be around 0.009. Maybe the delay is part of RunPod's processing of the data? I do not run jobs that are capable of such quick response time.

J

Jason•8/11/24, 11:56 PM

Or Try asking runpod to open ports for you then setup ws connection and just process a video on serverless on 1job

E

Encyrption•8/11/24, 11:56 PM

With my payloads I would not notice a 1.41 second delay

T

teddycatsdominoOP•8/12/24, 12:15 AM

Sorry, had to run out for a moment.

I initially set up a pod with WS but I don't know how to scale that. I then wanted to set up a worker with WS but it didn't seem like that was supported.

T

teddycatsdominoOP•8/12/24, 12:16 AM

I agree it might be part of Runpod's data processing. I posted partly to see if someone from Runpod would be able to confirm, or alternatively point me in the right direction if it were something on my end.

T

teddycatsdominoOP•8/12/24, 12:18 AM

@nerdylive Who would I ask at Runpod? If I could get serverless websockets working I think that might be ideal.

Tteddycatsdomino @nerdylive Who would I ask at Runpod? If I could get serverless websockets worki...

J

Jason•8/12/24, 12:53 AM

Contact button from the website

J

Jason•8/12/24, 12:53 AM

Or @flash-singh i guess, and explain to him what are you gonna use it for

Tteddycatsdomino Sorry, had to run out for a moment. I initially set up a pod with WS but I don...

J

Jason•8/12/24, 12:54 AM

Yep i think you have to go to support for opening ports

T

teddycatsdominoOP•8/12/24, 12:57 AM

I'll try that.

T

teddycatsdominoOP•8/12/24, 12:58 AM

We were hoping to get this working tonight. Got a fun little app that we want to let people try asap since the underlying libraries just came out.

F

flash-singh•8/12/24, 12:59 AM

are you using runsync? how are you running and getting job results?

F

flash-singh•8/12/24, 1:00 AM

websocket is possible but requires more work, much simpler without

T

teddycatsdominoOP•8/12/24, 1:52 AM

@flash-singh I am using runsync. The handler appears to process the job in 0.09 seconds, but the execution time on the Runpod dashboard is ~1.5s.

T

teddycatsdominoOP•8/12/24, 1:52 AM

I'm not sure why that would be, which is why I came here. I would love websockets on serverless, and I have websockets working on a pod. It's much better.

T

teddycatsdominoOP•8/12/24, 1:59 AM

Here are some relevant screenshots.

T

teddycatsdominoOP•8/12/24, 1:59 AM

I sent in a support request as well, but I am really hoping to be able to come up with a solution a bit faster if possible.

F

flash-singh•8/12/24, 2:11 AM

how big is your payload or output when job is done?

T

teddycatsdominoOP•8/12/24, 2:11 AM

~50kb

T

teddycatsdominoOP•8/12/24, 2:11 AM

They're video frames jpg encoded with longest side 512. Fairly small.

T

teddycatsdominoOP•8/12/24, 2:12 AM

Nothing that would explain a full second delay.

F

flash-singh•8/12/24, 2:12 AM

keep in mind that 1.5s accounts for time before job is even started by the worker, its the time between when job was given to when output is recieved

Runpod serverless overhead/slow

Similar Threads

Similar Threads

Similar Threads