O PC, why are you so slow?

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('Cl

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()
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.

StackExchange Code Review Q#135184, answer score: 17