CODEWITHSUNDEEP
pythonstack-trace
dwich
dwich

Reputation: 1723

Why is traceback.extract_stack() in Python so slow?

During tests I found out that calling traceback.extract_stack() is very slow. The price for getting stack track is comparable to executing a database query.

I'm wondering if I'm doing something wrong or missing something. What's surprising for me that I suppose calling extract_stack() is an internal call in Python, it's executed during the runtime in memory and should be super fast if not instant. In contrast calling database query involves external service (network communication) etc.

Example code is below. You can try how much time it takes to retrieve traceback in let say 20.000 iterations and how fast it is retrieving just first few items from the stack trace - set the limit=None parameter to something else.

My tests showed various results on various systems/configurations but all have in common that calling a stack trace is not orderds of magnitude cheaper, its almost the same as calling SQL insert.

           20k SQL inserts | 20k stack traces
Win                5.4 sec           14.4 sec
FreeBSD            5.0 sec            3.7 sec
Ubuntu GCP        16.6 sec            2.4 sec

Windows: laptop, local SSD. FreeBSD: server, local SSD. Ubuntu: Google Cloud, shared SSD.

Am I doing something wrong or is there any explanation why is traceback.extract_stack() so slow? Can I retrieve stack trace somehow faster?

Example code. Run $ pip install pytest and then $ pytest -s -v

import datetime
import unittest
import traceback


class TestStackTrace(unittest.TestCase):

    def test_stack_trace(self):
        start_time = datetime.datetime.now()
        iterations = 20000
        for i in range(0, iterations):
            stack_list = traceback.extract_stack(limit=None)  # set 0, 1, 2...
            stack_len = len(stack_list)
            self.assertEqual(1, 1)
        finish_time = datetime.datetime.now()
        print('\nStack length: {}, iterations: {}'.format(stack_len, iterations))
        print('Trace elapsed time: {}'.format(finish_time - start_time))

You don't need it but if you want the comparison with SQL insert, here it is. Just insert it as a second test method in the TestStackTrace class. Run CREATE DATABASE pytest1; and CREATE TABLE "test_table1" (num_value BIGINT, str_value VARCHAR(10));

def test_sql_query(self):
    start_time = datetime.datetime.now()
    con_str = "host='127.0.0.1' port=5432 user='postgres' password='postgres' dbname='pytest1'"
    con = psycopg2.connect(con_str)
    con.autocommit = True
    con.set_session(isolation_level='READ COMMITTED')
    cur = con.cursor()
    for i in range(0, 20000):
        cur.execute('INSERT INTO test_table1 (num_value, str_value) VALUES (%s, %s) ', (i, i))
    finish_time = datetime.datetime.now()
    print('\nSQL elapsed time: {}'.format(finish_time - start_time))

Upvotes: 5

Views: 779

Answers (1)

blhsing
blhsing

Reputation: 106543

traceback.extract_stack() is not an internal call in Python implemented in C. The entire traceback module is implemented in Python, which is why it is relatively slow. Since stack traces are typically only required during debugging, its performance usually isn't a concern. You may have to re-implement it as a C/C++ extension on your own if you really need a high-performance version of it.

Upvotes: 2

Related Questions