[BUG] In load execution start time and program start gap is large - Async Azure Function APP

[Nilabrata]

Investigative information

• Python Version: 3.10
• Function Runtime Version: 4.11.2.19273
• Core Tools version: 4.0.4829

Repro steps

1. Using JMeter we are hitting our end points. JMeter Configuration Ramp Up Time - 0 s, Number of Threads (Users) - 100

Expected behavior

1. When we are hitting one request at a time, it takes 1000 ms to respond. As we made the function asynchronous and we are sending request from 100 users parallelly it should take 1000ms to complete all 100 request.

Actual behavior

1. Actually It is taking 1 min 18 sec. When we checked the log we noticed one behavior that there is a large time gap between execution start time and program start time.

Contents of the requirements.txt file:

azure-functions == 1.13.3 pycopg2-binary==2.9.3

[bhagyshricompany]

Thanks for reporting will check and update

[gavin-aguiar]

@Nilabrata Could you please share a sample code which you are using to tests this so that we can repro this on our end.

[Nilabrata]

@gavin-aguiar, Below I am sharing code sample of init.py file -

from decimal import Decimal
import logging
import azure.functions as func
import psycopg2
import simplejson as json

connection_str = "dbname='dbname' user= 'user' host="host" ssImode='require password='password' "
db_conn = psycopg2.connect(connection_str)
logging.info(Connection Established’)
psycopg2.pooling = False
db_conn = [db_conn]

async def main(req: func.HttpRequest) -> func.HttpResponse:
  logging.info('Httptrigger Python HtTP trigger function processed a request.")

  if req.method == 'POST':
    request_body = req.get_json()

    db_data = await query_database()
    # Here example of data fetch from table
    # db_data = [(51558,'abc', "100', Decimal('0.0400000000'), 0), (51558, 'xyz', '101', Decimal('0.1500000000'), 0)]

    #here inserting db_data data to other table.
    await insert_query_database (db_data)

    logging.critical("HttpTrigger calculation Started")

    result1 = await sum_function(request_body, db_data)
    result2 = await product_function(request_body, db_data)

    logging.critical("HttpTrigger calculation ENDED")

    final_result = await formated_output(result1, result2, request_body)

    return func.HttpResponse(body= json.dumps(final_result), status_code=200, mimetype="application/json")

async def sum_function(request_body, db_data):
  allocation_list = sum([len(item) for item in request_body]) * float(db_data[0][3])
  return allocation_list

async def product_function(req_body, db_data):

  temp = 1
  for j in range(20):
    for i in range(1, 1000):
      for item in req_body:

        score = j * i * len(item)
        temp = score * temp

  temp = temp * float(db_data[0][3])
  return temp

async def formated_output (sum1, prod1, request_body):
  for item in request_body:
    item['score'] = 100 + 2 * (sum1 + prod1)
  return request body

async def insert_query_database(db_data):
  cursor = db_conn[0].cursor()
  cursor.execute("INSERT INTO table2 (allocation) VALUES (" + str(db_data[0][2]) + ")")
  db_conn[0].commit()
  cursor.close()

async def query_database():

  try:
    cursor = db_conn[0].cursor()
    cursor.execute("select * from table1")
    row = cursor.fetchone()
    db_data = []

    while row is not None:
      db_data.append(row)
      row = cursor.fetchone()
    return db data
  except Exception as error:
    logging.error("Query database" + str(error))`

Note: Please change DB connection string.

If your run this code with JMETER you can see response time is increasing constantly.

[Nilabrata]

@gavin-aguiar, If you anything to proceed with triage please let me know

[Nilabrata]

@gavin-aguiar, Below sharing a simpler version of code which will be easy for triage -

import azure.functions as func
import simplejson as json

async def main(req: func.HttpRequest) -> func.HttpResponse:

  if req.method == 'POST':
    req_body = req.get_json()
    request_body = req_body
    final_result = await product_function(request_body)
    return func.HttpResponse(body= json.dumps(final_result), status_code=200, mimetype="application/json")

async def product_function(req_body):
  temp = 1
  for j in range(1, 200):
    for i in range(1, 100):
      for item in req_body:
        score = 2 * len(item) + i
        temp = temp + score
  return temp

Let me know if you need anything else

[gavin-aguiar]

@Nilabrata Even though you are using async, the calls you are making are compute heavy. In this case the python GIL locks the thread till the execution is completed before proceeding to the next execution.

Here are some sample tests I conducted with the duration results

import azure.functions as func
from aiohttp_requests import requests as r
import requests

app = func.FunctionApp(http_auth_level=func.AuthLevel.ANONYMOUS)

@app.route(route="computeheavy")
async def computeheavy(req: func.HttpRequest) -> func.HttpResponse:
    pi = 0
    accuracy = 10000000

    for i in range(0, accuracy):
        pi += ((4.0 * (-1)**i) / (2*i + 1))

    return func.HttpResponse(f"{pi}", status_code=200)
# http_req_duration..............: avg=21.4s    min=9.05s    med=21.61s   max=34.16s   p(90)=32.73s   p(95)=33.44s

@app.route(route="notcomputeheavy")
async def notcomputeheavy(req: func.HttpRequest) -> func.HttpResponse:
    response = await r.get("https://raw.githubusercontent.com/vrdmr/AzFunctionsPythonPerformance/master/TestFile")
    return func.HttpResponse(await response.text())
# http_req_duration..............: avg=416.22ms min=68.35ms med=390.86ms max=2.41s    p(90)=684.26ms p(95)=747.65ms

@app.route(route="notcomputeheavy1")
async def notcomputeheavy1(req: func.HttpRequest) -> func.HttpResponse:
    response =  requests.get("https://raw.githubusercontent.com/vrdmr/AzFunctionsPythonPerformance/master/TestFile")
    return func.HttpResponse(str(response.text))
# http_req_duration..............: avg=1.44s   min=97.49ms med=449.96ms max=6s       p(90)=5.25s   p(95)=5.39s

From the first function 'computeheavy' you can see that even though the functions are async the http duration times are averaging around 21s. The second function 'notcomputeheavy' is using async too but since it not too compute heavy, aiohttp_requests processed them asynchronously with average time of 0.4s The third function 'notcomputeheavy1' has a higher execution time since even thought its using async, the requests library processes all calls synchronously .

For more details on GIL refer to this article