Lesson Learned #516:Measuring and Optimizing Application Performance

A few days ago, I worked on a support case where the customer reported that their process was taking too long. I want to share the lessons we learned about measuring execution and reviewing performance. Our customer mentioned that their process was taking over 15 seconds to complete and involved running the following query: SELECT TOP 10000 ID, ABS(CHECKSUM(NEWID()) % 1000) AS Value FROM [MSxyzTest].[_x_y_z_MS_HighCPU].

INFO:root:Connecting to the DB dbName - Thread id 14476 - (Attempt 1/3)
INFO:root:Connected to the Database in dbName - Thread id 14476 - 0.0358 seconds ---
INFO:root:(SimpleInefficiency) - Fetching 10000 rows...
INFO:root:Function took 14.9479 seconds.

Checking Query Data Store QDS first running the following query, it reported that the execution time only takes 5 ms. and the connection time took 3 ms. This indicates that we need to investigate more deeply to understand what is causing the delay.

SELECT 
    qsqt.query_sql_text AS QueryText,
    qsq.query_id,
    COUNT(qrs.count_executions) AS TotalExecutions,
    SUM(qrs.count_executions) AS TotalExecutionCount,
    MIN(qrs.first_execution_time) AS FirstExecutionTime,
    MAX(qrs.last_execution_time) AS LastExecutionTime,
    MIN(qrs.avg_duration / 1000.0) AS MinDurationMs,  -- Convert to milliseconds
    MAX(qrs.avg_duration / 1000.0) AS MaxDurationMs,  -- Convert to milliseconds
    AVG(qrs.avg_duration / 1000.0) AS AvgDurationMs   -- Convert to milliseconds
FROM 
    sys.query_store_query_text AS qsqt
INNER JOIN 
    sys.query_store_query AS qsq
    ON qsqt.query_text_id = qsq.query_text_id
INNER JOIN 
    sys.query_store_plan AS qsp
    ON qsq.query_id = qsp.query_id
INNER JOIN 
    sys.query_store_runtime_stats AS qrs
    ON qsp.plan_id = qrs.plan_id
WHERE 
    qsqt.query_sql_text LIKE '%SELECT TOP 10000 ID, ABS(CHECKSUM(NEWID())%'
GROUP BY 
    qsqt.query_sql_text, qsq.query_id
ORDER BY 
    TotalExecutionCount DESC;

We started to ask to our customer to add counters to the function they are executing to determine in which part of the code was causing the delay. Additionally, we enabled cProfiler to determine the bottleneck. 

INFO:root:Connecting to the DB dbName - Thread id 36028 - (Attempt 1/3)
INFO:root:Connected to the Database in dbName - Thread id 36028 - 0.3497 seconds ---
INFO:root:(SimpleInefficiency) - Fetching 10000 rows...
INFO:root:Query executed in 0.2049 seconds with 10000 rows.
INFO:root:Iteration 1/50 took 0.3562 seconds.
INFO:root:Iteration 2/50 took 0.3641 seconds.
INFO:root:Iteration 3/50 took 0.3493 seconds.
INFO:root:Iteration 4/50 took 0.2917 seconds.
INFO:root:Iteration 5/50 took 0.2673 seconds.
INFO:root:Iteration 6/50 took 0.4156 seconds.
INFO:root:Iteration 7/50 took 0.3096 seconds.
INFO:root:Iteration 8/50 took 0.3157 seconds.
INFO:root:Iteration 9/50 took 0.4182 seconds.
INFO:root:Iteration 10/50 took 0.3419 seconds.
INFO:root:Iteration 11/50 took 0.3483 seconds.
INFO:root:Iteration 12/50 took 0.3504 seconds.
INFO:root:Iteration 13/50 took 0.3376 seconds.
INFO:root:Iteration 14/50 took 0.2799 seconds.
INFO:root:Iteration 15/50 took 0.2698 seconds.
INFO:root:Iteration 16/50 took 0.2988 seconds.
INFO:root:Iteration 17/50 took 0.2899 seconds.
INFO:root:Iteration 18/50 took 0.2672 seconds.
INFO:root:Iteration 19/50 took 0.2886 seconds.
INFO:root:Iteration 20/50 took 0.2993 seconds.
INFO:root:Iteration 21/50 took 0.2828 seconds.
INFO:root:Iteration 22/50 took 0.2685 seconds.
INFO:root:Iteration 23/50 took 0.2702 seconds.
INFO:root:Iteration 24/50 took 0.2639 seconds.
INFO:root:Iteration 25/50 took 0.2607 seconds.
INFO:root:Iteration 26/50 took 0.2591 seconds.
INFO:root:Iteration 27/50 took 0.2773 seconds.
INFO:root:Iteration 28/50 took 0.2818 seconds.
INFO:root:Iteration 29/50 took 0.2980 seconds.
INFO:root:Iteration 30/50 took 0.2824 seconds.
INFO:root:Iteration 31/50 took 0.3103 seconds.
INFO:root:Iteration 32/50 took 0.3020 seconds.
INFO:root:Iteration 33/50 took 0.2706 seconds.
INFO:root:Iteration 34/50 took 0.2819 seconds.
INFO:root:Iteration 35/50 took 0.2846 seconds.
INFO:root:Iteration 36/50 took 0.2786 seconds.
INFO:root:Iteration 37/50 took 0.2939 seconds.
INFO:root:Iteration 38/50 took 0.2989 seconds.
INFO:root:Iteration 39/50 took 0.2860 seconds.
INFO:root:Iteration 40/50 took 0.2788 seconds.
INFO:root:Iteration 41/50 took 0.2820 seconds.
INFO:root:Iteration 42/50 took 0.2674 seconds.
INFO:root:Iteration 43/50 took 0.2927 seconds.
INFO:root:Iteration 44/50 took 0.2777 seconds.
INFO:root:Iteration 45/50 took 0.2758 seconds.
INFO:root:Iteration 46/50 took 0.2706 seconds.
INFO:root:Iteration 47/50 took 0.2591 seconds.
INFO:root:Iteration 48/50 took 0.2618 seconds.
INFO:root:Iteration 49/50 took 0.2584 seconds.
INFO:root:Iteration 50/50 took 0.2990 seconds.
INFO:root:Function took 16.0525 seconds.
         4573380 function calls in 16.054 seconds

   Ordered by: internal time
   List reduced from 184 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   13.985   13.985   16.053   16.053 GiveNotesPerformance.py:1393(RunSimpleInefficiencyWithTiming)
        1    0.826    0.826    0.850    0.850 {built-in method pyodbc.connect}
   499997    0.342    0.000    0.684    0.000 random.py:284(randrange)
   499997    0.186    0.000    0.261    0.000 random.py:235(_randbelow_with_getrandbits)
        1    0.158    0.158    0.158    0.158 {method 'fetchall' of 'pyodbc.Cursor' objects}


         4573380 function calls in 16.054 seconds

   Ordered by: call count
   List reduced from 184 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  1499991    0.081    0.000    0.081    0.000 {built-in method _operator.index}
   567948    0.045    0.000    0.045    0.000 {method 'getrandbits' of '_random.Random' objects}
   500013    0.038    0.000    0.038    0.000 {method 'append' of 'list' objects}
   499997    0.342    0.000    0.684    0.000 random.py:284(randrange)
   499997    0.186    0.000    0.261    0.000 random.py:235(_randbelow_with_getrandbits)

Finally, we found that our the customer's function involved 50 iterations to check if a row existed in an array and every interaction is taking 0.2 seconds and as they have multiple calls that is causing that the data management of the function took 15 seconds. 

Once we were able to determine the issue, we suggested to optimize the code making more efficient and reducing the execution time. 

INFO:root:Connecting to the DB dbName - Thread id 38944 - (Attempt 1/3)
INFO:root:Connected to the Database in dbName - Thread id 38944 - 0.3197 seconds ---
INFO:root:(SimpleInefficiency) - Fetching 10000 rows...
INFO:root:Query executed in 0.2064 seconds with 10000 rows.
INFO:root:Iteration 1/50 took 0.0189 seconds.
INFO:root:Iteration 2/50 took 0.0167 seconds.
INFO:root:Iteration 3/50 took 0.0161 seconds.
INFO:root:Iteration 4/50 took 0.0162 seconds.
INFO:root:Iteration 5/50 took 0.0156 seconds.
INFO:root:Iteration 6/50 took 0.0168 seconds.
INFO:root:Iteration 7/50 took 0.0177 seconds.
INFO:root:Iteration 8/50 took 0.0170 seconds.
INFO:root:Iteration 9/50 took 0.0154 seconds.
INFO:root:Iteration 10/50 took 0.0163 seconds.
INFO:root:Iteration 11/50 took 0.0176 seconds.
INFO:root:Iteration 12/50 took 0.0156 seconds.
INFO:root:Iteration 13/50 took 0.0163 seconds.
INFO:root:Iteration 14/50 took 0.0161 seconds.
INFO:root:Iteration 15/50 took 0.0158 seconds.
INFO:root:Iteration 16/50 took 0.0167 seconds.
INFO:root:Iteration 17/50 took 0.0154 seconds.
INFO:root:Iteration 18/50 took 0.0157 seconds.
INFO:root:Iteration 19/50 took 0.0169 seconds.
INFO:root:Iteration 20/50 took 0.0167 seconds.
INFO:root:Iteration 21/50 took 0.0167 seconds.
INFO:root:Iteration 22/50 took 0.0166 seconds.
INFO:root:Iteration 23/50 took 0.0153 seconds.
INFO:root:Iteration 24/50 took 0.0164 seconds.
INFO:root:Iteration 25/50 took 0.0162 seconds.
INFO:root:Iteration 26/50 took 0.0176 seconds.
INFO:root:Iteration 27/50 took 0.0157 seconds.
INFO:root:Iteration 28/50 took 0.0170 seconds.
INFO:root:Iteration 29/50 took 0.0199 seconds.
INFO:root:Iteration 30/50 took 0.0167 seconds.
INFO:root:Iteration 31/50 took 0.0134 seconds.
INFO:root:Iteration 32/50 took 0.0131 seconds.
INFO:root:Iteration 33/50 took 0.0165 seconds.
INFO:root:Iteration 34/50 took 0.0169 seconds.
INFO:root:Iteration 35/50 took 0.0176 seconds.
INFO:root:Iteration 36/50 took 0.0222 seconds.
INFO:root:Iteration 37/50 took 0.0167 seconds.
INFO:root:Iteration 38/50 took 0.0182 seconds.
INFO:root:Iteration 39/50 took 0.0168 seconds.
INFO:root:Iteration 40/50 took 0.0179 seconds.
INFO:root:Iteration 41/50 took 0.0171 seconds.
INFO:root:Iteration 42/50 took 0.0161 seconds.
INFO:root:Iteration 43/50 took 0.0187 seconds.
INFO:root:Iteration 44/50 took 0.0166 seconds.
INFO:root:Iteration 45/50 took 0.0148 seconds.
INFO:root:Iteration 46/50 took 0.0159 seconds.
INFO:root:Iteration 47/50 took 0.0174 seconds.
INFO:root:Iteration 48/50 took 0.0159 seconds.
INFO:root:Iteration 49/50 took 0.0134 seconds.
INFO:root:Iteration 50/50 took 0.0181 seconds.
INFO:root:Function took 1.9494 seconds.
         4073646 function calls in 1.950 seconds

   Ordered by: internal time
   List reduced from 185 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.715    0.715    0.718    0.718 {built-in method pyodbc.connect}
   500000    0.283    0.000    0.577    0.000 random.py:284(randrange)
        1    0.163    0.163    0.163    0.163 {method 'close' of 'pyodbc.Connection' objects}
        1    0.161    0.161    0.161    0.161 {method 'fetchall' of 'pyodbc.Cursor' objects}
   500000    0.158    0.000    0.222    0.000 random.py:235(_randbelow_with_getrandbits)


         4073646 function calls in 1.950 seconds

   Ordered by: call count
   List reduced from 185 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  1500000    0.072    0.000    0.072    0.000 {built-in method _operator.index}
   568140    0.041    0.000    0.041    0.000 {method 'getrandbits' of '_random.Random' objects}
   500000    0.283    0.000    0.577    0.000 random.py:284(randrange)
   500000    0.158    0.000    0.222    0.000 random.py:235(_randbelow_with_getrandbits)
   500000    0.106    0.000    0.683    0.000 random.py:358(randint)

Our lessons learned here, serves as a reminder of the importance of profiling and measuring code performance. By capturing execution times for queries, connections, and data processing, we gain the insights needed to build faster, more reliable, and cost-effective applications. 

Whether you're troubleshooting performance issues or designing scalable systems, remember: measure first, optimize second.

Example Python Code

    # Scenario N15 - Extreme Data Inefficiency
    if CURRENT_SCENARIO == EXTREME_DATA_INEFFICIENCY:
        pshow_function_time=True
        with cProfile.Profile() as Profile:
            RunSimpleInefficiencyWithTiming(row_count=10000, iterations=50,show_query_time=True,efficient=True,show_function_time=pshow_function_time)
            if(pshow_function_time==True):
                results = pstats.Stats(Profile)
                results.strip_dirs().sort_stats('tottime').print_stats(5)
                results.strip_dirs().sort_stats('ncalls').print_stats(5)

def RunSimpleInefficiencyWithTiming(row_count=10000, iterations=1, show_query_time=True, efficient=False, show_function_time=False):
    try:
        function_query_time = time.time()
        conn, dbNameReturn = ConnectToTheDB()
        if conn is None:
            logging.info("Error establishing connection to the database.")
            return

        cursor = conn.cursor()
        logging.info(f"(SimpleInefficiency) - Fetching {row_count} rows...")

        # Efficient query execution
        start_query_time = time.time()
        cursor.execute(f"SELECT TOP {row_count} ID, ABS(CHECKSUM(NEWID()) % 1000) AS Value FROM [MSxyzTest].[_x_y_z_MS_HighCPU]")
        rows = cursor.fetchall()
        query_execution_time = time.time() - start_query_time

        if show_query_time:
            logging.info(f"Query executed in {query_execution_time:.4f} seconds with {len(rows)} rows.")

        # Processing
        for iteration in range(iterations):
            start_iteration_time = time.time()  # Start timing for this iteration

            if efficient:
                # Efficient processing
                unique_ids = {row.ID * random.randint(100, 1000) for row in rows}
            else:
                # Inefficient processing
                unique_ids = []
                for row in rows:
                    if row.ID not in unique_ids:
                        unique_ids.append(row.ID * random.randint(100, 1000))

            iteration_time = time.time() - start_iteration_time  # Calculate time for this iteration
            if show_function_time==True:
                logging.info(f"Iteration {iteration + 1}/{iterations} took {iteration_time:.4f} seconds.")

        conn.close()
        function_stop_time = time.time() - function_query_time  # Calculate time for this function
        logging.info(f"Function took {function_stop_time:.4f} seconds.")

    except Exception as e:
        logging.error(f"An error occurred in RunSimpleInefficiencyWithTiming: {e}")