Thursday, June 6, 2013

Performance profiling a Python script...

A Python script I wrote takes Infoblox DHCP logs from syslog and puts them info a Python sqlite database for historical storage and quick searches.

It was taking >55 minutes for the script to import a 250mb file.

What follows is an explanation of how I was able to significantly reduce this time.  


The first thing is try and get an understanding of what your script is doing and what pieces are taking the longest to execute.  To do this I setup a control group of 100,000 lines from the DHCP logs:

tail -100000 infoblox.log > infoblox-100000.log

Then I ran my script against this with the Python cProfiler:

python -m cProfile  ./lease2sql-b.py -o -f infoblox-100000.log 

This produces the following output:

         3012531 function calls (3012404 primitive calls) in 19.866 seconds
   Ordered by: standard name
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 UserDict.py:4(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:1077(Logger)
        1    0.000    0.000    0.000    0.000 __init__.py:1092(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:1104(setLevel)
   403646    0.178    0.000    0.542    0.000 __init__.py:1110(debug)
    30734    0.018    0.000    0.059    0.000 __init__.py:1122(info)
        1    0.000    0.000    0.000    0.000 __init__.py:1262(addHandler)
   434380    0.153    0.000    0.153    0.000 __init__.py:1310(getEffectiveLevel)
   434380    0.251    0.000    0.405    0.000 __init__.py:1324(isEnabledFor)
        1    0.000    0.000    0.000    0.000 __init__.py:1351(RootLogger)
        1    0.000    0.000    0.000    0.000 __init__.py:1357(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:1365(LoggerAdapter)
        1    0.000    0.000    0.000    0.000 __init__.py:1471(basicConfig)
    30734    0.049    0.000    0.113    0.000 __init__.py:1586(info)
   403646    0.383    0.000    0.961    0.000 __init__.py:1594(debug)
        1    0.000    0.000    0.000    0.000 __init__.py:1652(NullHandler)
        3    0.000    0.000    0.000    0.000 __init__.py:182(_checkLevel)
        3    0.000    0.000    0.000    0.000 __init__.py:210(_acquireLock)
        3    0.000    0.000    0.000    0.000 __init__.py:219(_releaseLock)
        1    0.000    0.000    0.000    0.000 __init__.py:230(LogRecord)
        2    0.002    0.001    0.006    0.003 __init__.py:24()
        1    0.000    0.000    0.000    0.000 __init__.py:346(Formatter)
        2    0.000    0.000    0.000    0.000 __init__.py:390(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:490(BufferingFormatter)
        1    0.000    0.000    0.000    0.000 __init__.py:532(Filter)
        1    0.000    0.000    0.000    0.000 __init__.py:569(Filterer)
        2    0.000    0.000    0.000    0.000 __init__.py:574(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:6()
        1    0.000    0.000    0.000    0.000 __init__.py:631(_addHandlerRef)
        1    0.000    0.000    0.000    0.000 __init__.py:641(Handler)
        1    0.000    0.000    0.000    0.000 __init__.py:650(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:679(createLock)
        1    0.000    0.000    0.000    0.000 __init__.py:749(setFormatter)
        1    0.000    0.000    0.000    0.000 __init__.py:805(StreamHandler)
        1    0.000    0.000    0.000    0.000 __init__.py:812(__init__)
        1    0.000    0.000    0.000    0.000 __init__.py:872(FileHandler)
        1    0.000    0.000    0.000    0.000 __init__.py:932(PlaceHolder)
        1    0.000    0.000    0.000    0.000 __init__.py:979(Manager)
        1    0.000    0.000    0.000    0.000 __init__.py:984(__init__)
        1    0.000    0.000    0.000    0.000 atexit.py:37(register)
        1    0.000    0.000    0.000    0.000 atexit.py:6()
        1    0.000    0.000    0.000    0.000 bisect.py:1()
        1    0.000    0.000    0.000    0.000 calendar.py:126(Calendar)
        1    0.000    0.000    0.000    0.000 calendar.py:132(__init__)
        1    0.000    0.000    0.000    0.000 calendar.py:138(setfirstweekday)
        1    0.000    0.000    0.000    0.000 calendar.py:21(IllegalMonthError)
        1    0.000    0.000    0.000    0.000 calendar.py:255(TextCalendar)
        1    0.000    0.000    0.000    0.000 calendar.py:28(IllegalWeekdayError)
        1    0.000    0.000    0.000    0.000 calendar.py:372(HTMLCalendar)
        1    0.000    0.000    0.000    0.000 calendar.py:47(_localized_month)
        1    0.000    0.000    0.000    0.000 calendar.py:484(TimeEncoding)
        1    0.000    0.000    0.000    0.000 calendar.py:496(LocaleTextCalendar)
        2    0.000    0.000    0.000    0.000 calendar.py:52(__init__)
        1    0.000    0.000    0.000    0.000 calendar.py:531(LocaleHTMLCalendar)
        1    0.000    0.000    0.000    0.000 calendar.py:6()
        1    0.000    0.000    0.000    0.000 calendar.py:66(_localized_day)
        2    0.000    0.000    0.000    0.000 calendar.py:71(__init__)
        1    0.001    0.001    0.002    0.002 collections.py:1()
        1    0.000    0.000    0.000    0.000 collections.py:25(OrderedDict)
        1    0.000    0.000    0.000    0.000 collections.py:355(Counter)
        1    0.002    0.002    0.002    0.002 dbapi2.py:24()
        1    0.000    0.000    0.000    0.000 dbapi2.py:55(register_adapters_and_converters)
        1    0.000    0.000    0.000    0.000 getopt.py:15()
        2    0.000    0.000    0.000    0.000 getopt.py:187(do_shorts)
        2    0.000    0.000    0.000    0.000 getopt.py:202(short_has_arg)
        1    0.000    0.000    0.000    0.000 getopt.py:38(GetoptError)
        1    0.000    0.000    0.000    0.000 getopt.py:51(getopt)
        1    0.001    0.001    0.001    0.001 heapq.py:31()
        1    0.000    0.000    0.000    0.000 keyword.py:11()
   100000    0.369    0.000   19.752    0.000 lease2sql-b.py:130(processline)
        1    0.090    0.090   19.842   19.842 lease2sql-b.py:174(onetimerun)
        1    0.000    0.000   19.842   19.842 lease2sql-b.py:218(main)
        1    0.007    0.007   19.866   19.866 lease2sql-b.py:55()
    15367    0.124    0.000   17.815    0.001 lease2sql-b.py:88(insertInfoDb)
        1    0.000    0.000    0.000    0.000 parser.py:147(_resultbase)
        1    0.000    0.000    0.000    0.000 parser.py:165(parserinfo)
        1    0.000    0.000    0.000    0.000 parser.py:200(__init__)
        7    0.000    0.000    0.000    0.000 parser.py:215(_convert)
        1    0.000    0.000    0.000    0.000 parser.py:290(parser)
        1    0.000    0.000    0.000    0.000 parser.py:292(__init__)
        1    0.000    0.000    0.000    0.000 parser.py:337(_result)
        1    0.000    0.000    0.000    0.000 parser.py:39(_timelex)
        1    0.007    0.007    0.010    0.010 parser.py:7()
        1    0.000    0.000    0.000    0.000 parser.py:700(_tzparser)
        1    0.000    0.000    0.000    0.000 parser.py:702(_result)
        1    0.000    0.000    0.000    0.000 parser.py:707(_attr)
        1    0.000    0.000    0.000    0.000 posixpath.py:43(normcase)
   100002    0.055    0.000    0.198    0.000 re.py:188(compile)
   100002    0.109    0.000    0.142    0.000 re.py:228(_compile)
        1    0.000    0.000    0.000    0.000 relativedelta.py:15(weekday)
        7    0.000    0.000    0.000    0.000 relativedelta.py:18(__init__)
        1    0.000    0.000    0.000    0.000 relativedelta.py:45(relativedelta)
        1    0.000    0.000    0.001    0.001 relativedelta.py:6()
       25    0.000    0.000    0.000    0.000 sre_compile.py:178(_compile_charset)
       25    0.000    0.000    0.000    0.000 sre_compile.py:207(_optimize_charset)
       20    0.000    0.000    0.000    0.000 sre_compile.py:24(_identityfunction)
     42/3    0.000    0.000    0.001    0.000 sre_compile.py:32(_compile)
       27    0.000    0.000    0.000    0.000 sre_compile.py:354(_simple)
        3    0.000    0.000    0.000    0.000 sre_compile.py:361(_compile_info)
        6    0.000    0.000    0.000    0.000 sre_compile.py:474(isstring)
        3    0.000    0.000    0.001    0.000 sre_compile.py:480(_code)
        3    0.000    0.000    0.003    0.001 sre_compile.py:495(compile)
      111    0.000    0.000    0.000    0.000 sre_parse.py:126(__len__)
      225    0.000    0.000    0.000    0.000 sre_parse.py:130(__getitem__)
       27    0.000    0.000    0.000    0.000 sre_parse.py:134(__setitem__)
      126    0.000    0.000    0.000    0.000 sre_parse.py:138(append)
    69/30    0.000    0.000    0.000    0.000 sre_parse.py:140(getwidth)
        3    0.000    0.000    0.000    0.000 sre_parse.py:178(__init__)
      251    0.000    0.000    0.000    0.000 sre_parse.py:182(__next)
      117    0.000    0.000    0.000    0.000 sre_parse.py:195(match)
      200    0.000    0.000    0.000    0.000 sre_parse.py:201(get)
       18    0.000    0.000    0.000    0.000 sre_parse.py:205(tell)
       33    0.000    0.000    0.000    0.000 sre_parse.py:257(_escape)
     13/3    0.000    0.000    0.001    0.000 sre_parse.py:301(_parse_sub)
     14/3    0.001    0.000    0.001    0.000 sre_parse.py:379(_parse)
        3    0.000    0.000    0.001    0.000 sre_parse.py:663(parse)
        3    0.000    0.000    0.000    0.000 sre_parse.py:67(__init__)
        9    0.000    0.000    0.000    0.000 sre_parse.py:72(opengroup)
        9    0.000    0.000    0.000    0.000 sre_parse.py:83(closegroup)
       42    0.000    0.000    0.000    0.000 sre_parse.py:90(__init__)
        1    0.000    0.000    0.003    0.003 threading.py:1()
        2    0.000    0.000    0.000    0.000 threading.py:101(RLock)
        1    0.000    0.000    0.000    0.000 threading.py:104(_RLock)
        2    0.000    0.000    0.000    0.000 threading.py:106(__init__)
        3    0.000    0.000    0.000    0.000 threading.py:121(acquire)
        3    0.000    0.000    0.000    0.000 threading.py:141(release)
        2    0.000    0.000    0.000    0.000 threading.py:181(Condition)
        1    0.000    0.000    0.000    0.000 threading.py:184(_Condition)
        2    0.000    0.000    0.000    0.000 threading.py:186(__init__)
        1    0.000    0.000    0.000    0.000 threading.py:226(_is_owned)
        1    0.000    0.000    0.000    0.000 threading.py:277(notify)
        1    0.000    0.000    0.000    0.000 threading.py:295(notifyAll)
        1    0.000    0.000    0.000    0.000 threading.py:304(_Semaphore)
        1    0.000    0.000    0.000    0.000 threading.py:352(_BoundedSemaphore)
        1    0.000    0.000    0.000    0.000 threading.py:364(Event)
        1    0.000    0.000    0.000    0.000 threading.py:367(_Event)
        1    0.000    0.000    0.000    0.000 threading.py:371(__init__)
        1    0.000    0.000    0.000    0.000 threading.py:385(set)
        1    0.000    0.000    0.000    0.000 threading.py:424(Thread)
        1    0.000    0.000    0.000    0.000 threading.py:436(__init__)
        1    0.000    0.000    0.000    0.000 threading.py:531(_set_ident)
        1    0.000    0.000    0.000    0.000 threading.py:56(_Verbose)
        6    0.000    0.000    0.000    0.000 threading.py:58(__init__)
        7    0.000    0.000    0.000    0.000 threading.py:63(_note)
        1    0.000    0.000    0.000    0.000 threading.py:733(_Timer)
        1    0.000    0.000    0.000    0.000 threading.py:762(_MainThread)
        1    0.000    0.000    0.000    0.000 threading.py:764(__init__)
        1    0.000    0.000    0.000    0.000 threading.py:771(_set_daemon)
        1    0.000    0.000    0.000    0.000 threading.py:802(_DummyThread)
        1    0.000    0.000    0.000    0.000 tz.py:152(_ttinfo)
        1    0.000    0.000    0.000    0.000 tz.py:191(tzfile)
        1    0.000    0.000    0.000    0.000 tz.py:31(tzutc)
        1    0.000    0.000    0.000    0.000 tz.py:475(tzrange)
        1    0.000    0.000    0.000    0.000 tz.py:54(tzoffset)
        1    0.000    0.000    0.000    0.000 tz.py:554(tzstr)
        1    0.001    0.001    0.002    0.002 tz.py:6()
        1    0.000    0.000    0.000    0.000 tz.py:629(_tzicalvtzcomp)
        1    0.000    0.000    0.000    0.000 tz.py:639(_tzicalvtz)
        1    0.000    0.000    0.000    0.000 tz.py:701(tzical)
        1    0.000    0.000    0.000    0.000 tz.py:83(tzlocal)
        1    0.000    0.000    0.000    0.000 tzwin.py:2()
        1    0.000    0.000    0.000    0.000 warnings.py:45(filterwarnings)
        1    0.000    0.000    0.000    0.000 weakref.py:47(__init__)
        1    0.000    0.000    0.000    0.000 {_sqlite3.connect}
        2    0.000    0.000    0.000    0.000 {_sqlite3.register_adapter}
        2    0.000    0.000    0.000    0.000 {_sqlite3.register_converter}
        3    0.000    0.000    0.000    0.000 {_sre.compile}
       12    0.000    0.000    0.000    0.000 {_sre.getlower}
        1    0.000    0.000    0.000    0.000 {built-in method utcfromtimestamp}
        3    0.000    0.000    0.000    0.000 {hasattr}
      287    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 {issubclass}
435198/435170    0.042    0.000    0.042    0.000 {len}
        2    0.000    0.000    0.000    0.000 {max}
        3    0.000    0.000    0.000    0.000 {method 'acquire' of 'thread.lock' objects}
      694    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
     7516    6.378    0.001    6.378    0.001 {method 'commit' of 'sqlite3.Connection' objects}
        1    0.000    0.000    0.000    0.000 {method 'cursor' of 'sqlite3.Connection' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    43541    9.485    0.000    9.485    0.000 {method 'execute' of 'sqlite3.Cursor' objects}
        2    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
    36025    1.715    0.000    1.715    0.000 {method 'fetchone' of 'sqlite3.Cursor' objects}
   100051    0.031    0.000    0.031    0.000 {method 'get' of 'dict' objects}
   134380    0.022    0.000    0.022    0.000 {method 'group' of '_sre.SRE_Match' objects}
        2    0.000    0.000    0.000    0.000 {method 'insert' of 'list' objects}
        3    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
       74    0.000    0.000    0.000    0.000 {method 'lower' of 'str' objects}
   100000    0.335    0.000    0.335    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
        2    0.000    0.000    0.000    0.000 {method 'release' of 'thread.lock' objects}
        9    0.000    0.000    0.000    0.000 {method 'remove' of 'list' objects}
   100000    0.052    0.000    0.052    0.000 {method 'rstrip' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'setter' of 'property' objects}
        2    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        6    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'toordinal' of 'datetime.date' objects}
       86    0.000    0.000    0.000    0.000 {min}
        1    0.000    0.000    0.000    0.000 {open}
       96    0.000    0.000    0.000    0.000 {ord}
       17    0.000    0.000    0.000    0.000 {range}
        5    0.000    0.000    0.000    0.000 {thread.allocate_lock}
        8    0.000    0.000    0.000    0.000 {thread.get_ident}
        1    0.000    0.000    0.000    0.000 {time.localtime}
        1    0.000    0.000    0.000    0.000 {time.time}


It took almost 20 seconds to process 100,000 lines and put them into the database.


Time to review where the script was hanging up.   Look for the line that took the most time and we find:

     7516    6.378    0.001    6.378    0.001 {method 'commit' of 'sqlite3.Connection' objects}

In my script, I run a sql.commit() on every single INSERT into the database.   What if I only commit changes once I am done inserting?  This is a huge performance increase.   After this change, execution is almost cut in half:

3005019 function calls (3004892 primitive calls) in 10.767 seconds

There is a downside to this, if the script gets interrupted in the middle and there is no commit(), I will loose all data from that run.   In my case this is no big deal, I need performance over reliability, I can always rerun the import.

What is the next big thing?

    43541    7.247    0.000    7.247    0.000 {method 'execute' of 'sqlite3.Cursor' objects}
    36025    1.469    0.000    1.469    0.000 {method 'fetchone' of 'sqlite3.Cursor' objects}

My cursor and fetchone objects.   This is probably related to queries.   What can I do to queries to make them faster?  Let review what we are looking up.  The two major searches are:

    sqdb.execute('SELECT ip FROM leaseinfo WHERE date = ? AND ip = ?', t)
    sqdb.execute('SELECT mac FROM macinfo WHERE mac = ? AND wukey = ?', t)
 Lets index the data in the database to make these searches faster:

    sqdb.execute('''CREATE INDEX idx1 ON leaseinfo(date, ip)''')
    sqdb.execute('''CREATE INDEX idx2 ON macinfo(mac, wukey)''')

Another huge improvement.   Execution time was cut by another 79%:

         3005019 function calls (3004892 primitive calls) in 2.354 seconds

We started out with the script taking around 19.8 seconds.  By delaying commits to disk and indexing databases, execution time was dropped to 2.3 seconds.     This is an 89% improvement in execution time!


Now, the real file import that was taking >55 minutes.  After making the changes above:

time ./lease2sql.py -o -f ./infoblox.log
real 0m34.230s
user 0m33.944s
sys 0m0.237s

34 seconds to import.  Huge improvement.   

No comments:

Post a Comment

Followers