Stephen Stephen - 19 days ago 7
Python Question

Python 3 Multiprocessing and Sockets

I have a client script that communicates with multiple servers. It appears from my testing and research that python's socket library is synchronous. No matter what I do, single socket variable or dynamic socket variables, the script will not send and receive data at the same time. Here's the basic version of my script using dynamic socket ids:

import socket
import logging
import os
import time
from time import time
import datetime
import multiprocessing

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logging.getLogger('requests').setLevel(logging.CRITICAL)
logger = logging.getLogger(__name__)

IP=[0,1,2,3,4,5]
IP[0] = '192.168.1.21'
IP[1] = '192.168.1.22'
IP[2] = '192.168.1.23'
IP[3] = '192.168.1.24'
IP[4] = '192.168.1.25'
IP[5] = '192.168.1.26'
PORT = 1292

def ClientWorker(ip, port, socketid):
name = multiprocessing.current_process().name
ts = time()
s = [0,1,2,3,4,5]
s[socketid] = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s[socketid].connect((ip, port))
s[socketid].send(b"Get status")
response = s[socketid].recv(50)
s[socketid].close()
print('Connection to {}:'.format(ip))
print('Process Took: {}'.format(time() - ts))

def main():
tsmain = time()
socketnum = 0
workers = []
for ipaddr in IP:
logger.info('Queueing {}'.format(ipaddr))
worker = multiprocessing.Process(target=ClientWorker, args=(ipaddr, PORT, socketnum))
workers.append(worker)
worker.start()
socketnum += 1
for w in workers:
w.join()
print('Main Took {}'.format(time() - tsmain))

if __name__ == '__main__':
main()


Multiprocessing output:

2016-07-06 10:32:17,178 - __main__ - INFO - Starting 192.168.1.21
2016-07-06 10:32:17,181 - __main__ - INFO - Starting 192.168.1.22
2016-07-06 10:32:17,181 - __main__ - INFO - Starting 192.168.1.23
2016-07-06 10:32:17,183 - __main__ - INFO - Starting 192.168.1.24
2016-07-06 10:32:17,184 - __main__ - INFO - Starting 192.168.1.25
2016-07-06 10:32:17,185 - __main__ - INFO - Starting 192.168.1.26
Connection to 192.168.1.22:
Process Took 0.36358118057250977
Connection to 192.168.1.25:
Process Took 0.37239646911621094
Connection to 192.168.1.21:
Process Took 0.3772423267364502
Connection to 192.168.1.26:
Process Took 0.4828777313232422
Connection to 192.168.1.24:
Process Took 0.6024985313415527
Connection to 192.168.1.23:
Process Took 0.7020003795623779
Main Took 0.708820104598999


It looks like all the processes are starting at pretty much the same time but each process takes longer to complete, which suggests only one socket can be open at once.

I've done research on twisted, asyncio & asyncore. I started going down the twisted road but I'm having trouble wrapping my head around that because the messages sent to each server will not be the same. The script will be designed to send different tasks to each server at the same time and wait for the results.

Any tips would be greatly appreciated. I've hit a wall with this.

Stephen

EDIT, More detailed output:

(0, 0) = Process-1 Work started: 2016-07-06 15:42:02.227847
(0, 1) = Process-2 Work started: 2016-07-06 15:42:02.228606
(0, 2) = Process-3 Work started: 2016-07-06 15:42:02.229448
(0, 3) = Process-4 Work started: 2016-07-06 15:42:02.231957
(0, 4) = Process-5 Work started: 2016-07-06 15:42:02.232951
(0, 5) = Process-6 Work started: 2016-07-06 15:42:02.233697
(1, 0) = Process-1 Setting up network socket 0 @ 2016-07-06 15:42:02.227894
(1, 1) = Process-2 Setting up network socket 1 @ 2016-07-06 15:42:02.228655
(1, 2) = Process-3 Setting up network socket 2 @ 2016-07-06 15:42:02.229498
(1, 3) = Process-4 Setting up network socket 3 @ 2016-07-06 15:42:02.232006
(1, 4) = Process-5 Setting up network socket 4 @ 2016-07-06 15:42:02.232994
(1, 5) = Process-6 Setting up network socket 5 @ 2016-07-06 15:42:02.233742
(2, 0) = Process-1 Completed network socket setup 0 @ 2016-07-06 15:42:02.228005 - took 0:00:00.000121
(2, 1) = Process-2 Completed network socket setup 1 @ 2016-07-06 15:42:02.228781 - took 0:00:00.000137
(2, 2) = Process-3 Completed network socket setup 2 @ 2016-07-06 15:42:02.229608 - took 0:00:00.000120
(2, 3) = Process-4 Completed network socket setup 3 @ 2016-07-06 15:42:02.232109 - took 0:00:00.000112
(2, 4) = Process-5 Completed network socket setup 4 @ 2016-07-06 15:42:02.233081 - took 0:00:00.000092
(2, 5) = Process-6 Completed network socket setup 5 @ 2016-07-06 15:42:02.233854 - took 0:00:00.000122
(3, 0) = Process-1 Connecting to network socket @ 2016-07-06 15:42:02.228046
(3, 1) = Process-2 Connecting to network socket @ 2016-07-06 15:42:02.228823
(3, 2) = Process-3 Connecting to network socket @ 2016-07-06 15:42:02.229647
(3, 3) = Process-4 Connecting to network socket @ 2016-07-06 15:42:02.232145
(3, 4) = Process-5 Connecting to network socket @ 2016-07-06 15:42:02.233109
(3, 5) = Process-6 Connecting to network socket @ 2016-07-06 15:42:02.233893
(4, 0) = Process-1 Connected to network socket @ 2016-07-06 15:42:02.232009 - took 0:00:00.003983
(4, 1) = Process-2 Connected to network socket @ 2016-07-06 15:42:02.232624 - took 0:00:00.003818
(4, 2) = Process-3 Connected to network socket @ 2016-07-06 15:42:02.233706 - took 0:00:00.004080
(4, 3) = Process-4 Connected to network socket @ 2016-07-06 15:42:02.235946 - took 0:00:00.003827
(4, 4) = Process-5 Connected to network socket @ 2016-07-06 15:42:02.236215 - took 0:00:00.003120
(4, 5) = Process-6 Connected to network socket @ 2016-07-06 15:42:02.237408 - took 0:00:00.003530
(5, 0) = Process-1 Beginning to send data to network socket @ 2016-07-06 15:42:02.228046
(5, 1) = Process-2 Beginning to send data to network socket @ 2016-07-06 15:42:02.228823
(5, 2) = Process-3 Beginning to send data to network socket @ 2016-07-06 15:42:02.229647
(5, 3) = Process-4 Beginning to send data to network socket @ 2016-07-06 15:42:02.232145
(5, 4) = Process-5 Beginning to send data to network socket @ 2016-07-06 15:42:02.233109
(5, 5) = Process-6 Beginning to send data to network socket @ 2016-07-06 15:42:02.233893
(6, 0) = Process-1 Completed data send to network socket @ 2016-07-06 15:42:02.232084 - took 0:00:00.000038
(6, 1) = Process-2 Completed data send to network socket @ 2016-07-06 15:42:02.232699 - took 0:00:00.000039
(6, 2) = Process-3 Completed data send to network socket @ 2016-07-06 15:42:02.233788 - took 0:00:00.000044
(6, 3) = Process-4 Completed data send to network socket @ 2016-07-06 15:42:02.236024 - took 0:00:00.000035
(6, 4) = Process-5 Completed data send to network socket @ 2016-07-06 15:42:02.236263 - took 0:00:00.000023
(6, 5) = Process-6 Completed data send to network socket @ 2016-07-06 15:42:02.237456 - took 0:00:00.000022
(7, 0) = Process-1 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.232102
(7, 1) = Process-2 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.232717
(7, 2) = Process-3 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.233809
(7, 3) = Process-4 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.236041
(7, 4) = Process-5 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.236274
(7, 5) = Process-6 Beginning to wait for data from network socket @ 2016-07-06 15:42:02.237467
(8, 0) = Process-1 Received data from network socket @ 2016-07-06 15:42:02.273043 - took 0:00:00.040980
(8, 1) = Process-2 Received data from network socket @ 2016-07-06 15:42:02.277420 - took 0:00:00.044757
(8, 2) = Process-3 Received data from network socket @ 2016-07-06 15:42:02.267754 - took 0:00:00.033984
(8, 3) = Process-4 Received data from network socket @ 2016-07-06 15:42:02.281372 - took 0:00:00.045383
(8, 4) = Process-5 Received data from network socket @ 2016-07-06 15:42:02.278337 - took 0:00:00.042100
(8, 5) = Process-6 Received data from network socket @ 2016-07-06 15:42:03.197792 - took 0:00:00.960364
(9, 0) = Process-1 Beginning to process response from server @ 2016-07-06 15:42:02.273101
(9, 1) = Process-2 Beginning to process response from server @ 2016-07-06 15:42:02.277494
(9, 2) = Process-3 Beginning to process response from server @ 2016-07-06 15:42:02.267812
(9, 3) = Process-4 Beginning to process response from server @ 2016-07-06 15:42:02.281444
(9, 4) = Process-5 Beginning to process response from server @ 2016-07-06 15:42:02.278390
(9, 5) = Process-6 Beginning to process response from server @ 2016-07-06 15:42:03.197861
(10, 0) = Process-1 Finished processing response from server @ 2016-07-06 15:42:02.273140 - took 0:00:00.000048
(10, 1) = Process-2 Finished processing response from server @ 2016-07-06 15:42:02.277529 - took 0:00:00.000043
(10, 2) = Process-3 Finished processing response from server @ 2016-07-06 15:42:02.267847 - took 0:00:00.000045
(10, 3) = Process-4 Finished processing response from server @ 2016-07-06 15:42:02.281475 - took 0:00:00.000038
(10, 4) = Process-5 Finished processing response from server @ 2016-07-06 15:42:02.278418 - took 0:00:00.000035
(10, 5) = Process-6 Finished processing response from server @ 2016-07-06 15:42:03.197889 - took 0:00:00.000035
(11, 0) = Process-1 Communicating with server to retreive additional information @ 2016-07-06 15:42:02.273156
(11, 1) = Process-2 Communicating with server to retreive additional information @ 2016-07-06 15:42:02.277544
(11, 2) = Process-3 Communicating with server to retreive additional information @ 2016-07-06 15:42:02.267865
(11, 3) = Process-4 Communicating with server to retreive additional information @ 2016-07-06 15:42:02.281488
(11, 4) = Process-5 Communicating with server to retreive additional information @ 2016-07-06 15:42:02.278432
(11, 5) = Process-6 Communicating with server to retreive additional information @ 2016-07-06 15:42:03.197903
(12, 0) = Process-1 Finished final retreival of data @ 2016-07-06 15:42:02.848586 - took 0:00:00.575468
(12, 1) = Process-2 Finished final retreival of data @ 2016-07-06 15:42:03.637331 - took 0:00:01.359825
(12, 2) = Process-3 Finished final retreival of data @ 2016-07-06 15:42:02.765458 - took 0:00:00.497645
(12, 3) = Process-4 Finished final retreival of data @ 2016-07-06 15:42:03.541048 - took 0:00:01.259597
(12, 4) = Process-5 Finished final retreival of data @ 2016-07-06 15:42:02.818199 - took 0:00:00.539810
(12, 5) = Process-6 Finished final retreival of data @ 2016-07-06 15:42:03.526207 - took 0:00:00.328342
(13, 0) = Process-1 Closing network socket 0 @ 2016-07-06 15:42:02.848643
(13, 1) = Process-2 Closing network socket 1 @ 2016-07-06 15:42:03.637387
(13, 2) = Process-3 Closing network socket 2 @ 2016-07-06 15:42:02.765536
(13, 3) = Process-4 Closing network socket 3 @ 2016-07-06 15:42:03.541101
(13, 4) = Process-5 Closing network socket 4 @ 2016-07-06 15:42:02.818264
(13, 5) = Process-6 Closing network socket 5 @ 2016-07-06 15:42:03.526262
(14, 0) = Process-1 Closed network socket 0 @ 2016-07-06 15:42:02.848719 - took 0:00:00.000086
(14, 1) = Process-2 Closed network socket 1 @ 2016-07-06 15:42:03.637463 - took 0:00:00.000086
(14, 2) = Process-3 Closed network socket 2 @ 2016-07-06 15:42:02.765647 - took 0:00:00.000128
(14, 3) = Process-4 Closed network socket 3 @ 2016-07-06 15:42:03.541168 - took 0:00:00.000075
(14, 4) = Process-5 Closed network socket 4 @ 2016-07-06 15:42:02.818365 - took 0:00:00.000114
(14, 5) = Process-6 Closed network socket 5 @ 2016-07-06 15:42:03.526333 - took 0:00:00.000080
(15, 0) = Process-1 Took 0:00:00.620923
(15, 1) = Process-2 Took 0:00:01.408908
(15, 2) = Process-3 Took 0:00:00.536262
(15, 3) = Process-4 Took 0:00:01.309261
(15, 4) = Process-5 Took 0:00:00.585469
(15, 5) = Process-6 Took 0:00:01.292729
(16, 0) = Process-1 Work finished: 2016-07-06 15:42:02.848763
(16, 1) = Process-2 Work finished: 2016-07-06 15:42:03.637487
(16, 2) = Process-3 Work finished: 2016-07-06 15:42:02.765685
(16, 3) = Process-4 Work finished: 2016-07-06 15:42:03.541191
(16, 4) = Process-5 Work finished: 2016-07-06 15:42:02.818397
(16, 5) = Process-6 Work finished: 2016-07-06 15:42:03.526357
Main Took 0:00:01.430665

Answer

I did indeed find out that my original code is good and that the discrepancies in timing were the result of the end machines being busy with other tasks or just slow to respond in general.

Comments