O PC, why are you so slow?

Question

In order to test some software I've written, I need to write values to a test harness with OLE for Process Control (OPC). The problem is, for a larger range of values I'm generating points for (say 10000), this code can take 15 seconds to execute. I need it to work in under 1 second.

import OpenOPC
import argparse
import sys
import time
from random import randint

def get_args():
    parser = argparse.ArgumentParser(description='Record data value changes')
    parser.add_argument('range', type=int, help='range of values to record')
    parser.add_argument('time', type=int, help='time to update values in seconds')
    return parser.parse_args()


def get_range_list(amount, val, end):
    return [
        ('flcon1:DataValue~Osiris_Test_Data_' + str(i + 1) + end, randint(0, val))
        for i in range(amount)
    ]


def get_time_list(amount, end):
    return [
        ('flcon1:DataValue~Osiris_Test_Data_' + str(i + 1) + end, time.strftime('%m/%d/%Y %H:%M:%S'))
        for i in range(amount)
    ]


def main():
    args = get_args()
    opc = OpenOPC.open_client('localhost')
    opc.connect('SISCO.AXS4ICCP.3')

    print('Logging test harness value changes')
    while True:
        try:
            t0 = time.clock()
            value_list = get_range_list(args.range, 9, '.Value')
            time_list = get_time_list(args.range, '.TimeStamp')

            opc.write(value_list)
            opc.write(time_list)

            print('Wrote values')

            with open(str(args.range) + '.' + str(args.time) + '_1-iccp_harness.log', 'a') as f:
                for i in xrange(0, args.range):
                    f.write('Osiris_Test_Data_' + str(i + 1) + ', realQTimetagExtended' + 
                            ', %g, %s, %s\n' % (value_list[i][1], 00, time_list[i][1]))

            t1 = time.clock()
            print t1-t0

            print('Logged values')
            time.sleep(args.time)

        except KeyboardInterrupt:
            opc.close()
            print('Closing down logger')
            sys.exit()


if __name__ == '__main__':
    main()

Answer 1

def get_range_list(amount, val, end):
    return [
        ('flcon1:DataValue~Osiris_Test_Data_' + str(i + 1) + end, randint(0, val))
        for i in range(amount)
    ]

You're only interested in the value of amount, not in the variable it produces itself. Have you tried using xrange instead? xrange is much faster than range.

Afar from that, I cut-out the OPC parts and ran the rest through a profiler.

python -m cProfile -s tottime CR_135184.py 1000000 1

Cut code:

import argparse
import sys
import time
from random import randint

def get_args():
    parser = argparse.ArgumentParser(description='Record data value changes')
    parser.add_argument('range', type=int, help='range of values to record')
    parser.add_argument('time', type=int, help='time to update values in seconds')
    return parser.parse_args()


def get_range_list(amount, val, end):
    return [
        ('flcon1:DataValue~Osiris_Test_Data_' + str(i + 1) + end, randint(0, val))
        for i in xrange(amount)
    ]


def get_time_list(amount, end):
    return [
        ('flcon1:DataValue~Osiris_Test_Data_' + str(i + 1) + end, time.strftime('%m/%d/%Y %H:%M:%S'))
        for i in xrange(amount)
    ]


def main():
    args = get_args()
    print('Logging test harness value changes')

    t0 = time.clock()
    value_list = get_range_list(args.range, 9, '.Value')
    time_list = get_time_list(args.range, '.TimeStamp')

    print(value_list)
    print(time_list)

    print('Wrote values')

    with open(str(args.range) + '.' + str(args.time) + '_1-iccp_harness.log', 'a') as f:
        for i in xrange(0, args.range):
            f.write('Osiris_Test_Data_' + str(i + 1) + ', realQTimetagExtended' + 
                    ', %g, %s, %s\n' % (value_list[i][1], 00, time_list[i][1]))

    t1 = time.clock()
    print t1-t0

    print('Logged values')


if __name__ == '__main__':
    main()

Result (the relevant parts):

Wrote values
7.145332
Logged values
         5001665 function calls (5001624 primitive calls) in 15.432 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   11.660   11.660   15.299   15.299 CR_135184.py:27(main)
  1000000    1.269    0.000    1.269    0.000 {time.strftime}
  1000000    0.876    0.000    0.925    0.000 random.py:175(randrange)
        1    0.551    0.551    1.708    1.708 CR_135184.py:13(get_range_list)
        1    0.510    0.510    1.779    1.779 CR_135184.py:20(get_time_list)
  1000000    0.232    0.000    1.157    0.000 random.py:238(randint)
  1000000    0.151    0.000    0.151    0.000 {method 'write' of 'file' objects}
        1    0.120    0.120   15.432   15.432 CR_135184.py:1(<module>)
  1000000    0.049    0.000    0.049    0.000 {method 'random' of '_random.Random' objects}

Basically, you're slowing down your code by checking the time. The generating of random numbers takes some time, but get_range_list and get_time_list are surprisingly fast.

The real bottleneck? Your OPC connection. And I'm not sure whether this can be fixed at all in code.

Answer 2

It's going to be hard to improve this very much, because your code is likely limited by the network IO you're doping to connect to OPC. On my machine I've disabled the OPC calls (I don't have it installed) and it runs through 10k values in about half a second. You will need to actually profile the code (python -m profile -s time ./opc.py 10000 1) to get an idea about what is actually taking all of the time. On my machine getting the random numbers takes the most time (once I make the changes below). That being said, here are some general micro-optimizations you might try.

Use generators whenever possible

I don't know if opc supports generators or requires a list, but if you can get away with a generator then do so; they'll definitely be better for memory usage, and often better for speed as well. In a similar vein, use xrange whenever possible

Use string formatting instead of concatenation

In cPython the peephole optimizer optimizes string concatenation for two strings, but falls apart past that. Use str.join instead to maintain linear time complexity.

Avoid any unnecessary IO, including to stdout for output

Any IO you do is going to slow things down. Try to not print things out.