Connection pooling in modbus binding

mbs38 · January 29, 2016, 11:03am

Hi ssalonen,

It seems that it eventually works, just like with @mbs38 (since there is not execute try 2 error)

The performance is still well below what I’ve seen with a single slave and hasn’t improved at all. I got 30 successful queries per second with a single slave and about 1 to 2 with 12 slaves. The performance also degrades over time, which I’ve seen with the unmodified 1.8 binding too. In the first couple of seconds after starting openhab it achieves between 3 and 5 successful queries per second and that slows down to 1 to 2 successful queries per second.


14:09:13.364 [ERROR] [i.modbus.io.ModbusRTUTransport:167  ] - Last request: 05 02 00 00 00 08 78 48
14:09:13.364 [ERROR] [i.modbus.io.ModbusRTUTransport:168  ] - failed to read: Error reading response
14:09:13.364 [ERROR] [w.m.io.ModbusSerialTransaction:198  ] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadInputDiscretesRequest@2ce4fef7. Serial parameters: net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]
14:09:13.411 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.411 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.412 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus5): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.412 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.412 [INFO ] [runtime.busevents             :26   ] - IRvorne state updated to CLOSED
14:09:13.412 [INFO ] [runtime.busevents             :26   ] - Klingel state updated to CLOSED
14:09:13.412 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Ampel'
14:09:13.412 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.413 [INFO ] [runtime.busevents             :26   ] - Stahltuer state updated to OPEN
14:09:13.413 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus5coils): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 1 ms
14:09:13.414 [INFO ] [runtime.busevents             :22   ] - agsBus7Out5 received command OFF
14:09:13.415 [INFO ] [runtime.busevents             :22   ] - agsBus7Out4 received command OFF
14:09:13.447 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.447 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.447 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus5coils): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.447 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'KlingelIRvorne'
14:09:13.448 [INFO ] [runtime.busevents             :26   ] - IRvorneEventShort state updated to OFF
14:09:13.448 [INFO ] [runtime.busevents             :26   ] - IRvorneEventLong state updated to OFF
14:09:13.452 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.452 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.453 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus3): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 3 ms
14:09:13.483 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.483 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.484 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus3): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.484 [INFO ] [runtime.busevents             :26   ] - Mitteleingang state updated to OPEN
14:09:13.484 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.484 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.484 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus17Discretes): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.518 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.518 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.518 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus17Discretes): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.519 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.519 [INFO ] [runtime.busevents             :26   ] - agsBus17Discrete state updated to CLOSED
14:09:13.519 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.519 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus2): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.542 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.542 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.542 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus2): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.543 [INFO ] [runtime.busevents             :26   ] - Holztuer state updated to OPEN
14:09:13.543 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.543 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.543 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus4): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.567 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus4): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.567 [INFO ] [runtime.busevents             :26   ] - Hintereingang state updated to OPEN
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.567 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBusMasterCoils): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.579 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBusMasterCoils): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.579 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlDoors state updated to ON
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.580 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlMasterSwitchOn state updated to ON
14:09:13.580 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.580 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlMasterSwitchOff state updated to ON
14:09:13.580 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus11): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 1 ms
14:09:13.643 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.643 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.644 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus11): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out0 state updated to OFF
14:09:13.644 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out2 state updated to ON
14:09:13.644 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out1 state updated to ON
14:09:13.644 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus8): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.647 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn2 state updated to OFF
14:09:14.089 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:80   ] - Unregistering service _openhab-server-ssl._tcp.local. at port 8443
14:09:14.151 [ERROR] [i.modbus.io.ModbusRTUTransport:167  ] - Last request: 08 01 00 00 00 18 3c 99
14:09:14.151 [ERROR] [i.modbus.io.ModbusRTUTransport:168  ] - failed to read: Error reading response
14:09:14.151 [ERROR] [w.m.io.ModbusSerialTransaction:198  ] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadCoilsRequest@78f7f111. Serial parameters: net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]
14:09:14.180 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:14.180 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:14.180 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus8): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:14.181 [INFO ] [runtime.busevents             :26   ] - agsBus8Out0 state updated to ON
14:09:14.181 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@373a1ecd[serialParameters=net.wimpi.modbus.util.SerialParameters@735e2852[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:14.181 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@373a1ecd[serialParameters=net.wimpi.modbus.util.SerialParameters@735e2852[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:14.181 [INFO ] [runtime.busevents             :26   ] - agsBus8Out1 state updated to ON

ssalonen · January 29, 2016, 8:06pm

Thank you very much, definetely that does not sound too good.

Even with the new logs I’m missing some log entries: we should get either “execute eventually succeeded with X tries…” or “execute try 3 reached max tries 3 error, throwing last error: …”. I have to test myself why we do not see those log messages.

I’ve also realized that the current implementation might still re-use the modbus transaction id even though the end point (modbus slave device) is the same. That definitely needs fixing, not sure if that might cause some of the slow downs or errors…

I have limited access to internet during the next two weeks but I will look at this and come up with a new version to test.

Thank you again both for trying this out!

mbs38 · February 1, 2016, 11:24pm

You’re welcome. If you come up with something new I’ll be happy to provide feedback again.

M

rossko57 · February 7, 2016, 1:19pm

Just a suggestion, while “queuing” is being looked into. I’m developing a multi-slave Modbus application; don’t have enough hardware yet to help much with testing. But I am playing with configuration so far as I can.

I set up two TCP slaves in openhab.cfg and see the expected timeouts as they don’t yet exist. Monitoring the actual communication attempts shows batches of four attempts, as expected from 1 try + 3 retries.

My observation is that the retry mechanism fixates on each slave in turn, i.e. 4 tries at slaveA, followed by 4 tries at slaveB. This is not ideal as one missing/faulty slave would appear to prevent polling of any remaining working slaves for a long while (4 x timeout periods)? It would be better if retry attempts could be scheduled to the back of the queue, so that normal polling of other slaves could take place in between retries. poll SlaveA(timeout) - poll SlaveB - poll SlaveC - retry Slave A etc.

That might all be completely impractical of course!! just offering for consideration. It’s only a problem when some other error already exists, but would help make Modbus based systems more robust.

mbs38 · February 8, 2016, 8:38pm

Good point.

ssalonen · February 14, 2016, 2:40pm

All right, have had some time to progress this project once again. So I commented a while ago the issue on transaction ids, that is an issue only for TCP modbus since the transaction id is not used with serial.

My tests with local modbus TCP server can now handle huge amount of queries and commands simultaneously so I think we are going to the right direction.

I’ve been trying to figure the remaining serial issues and starting to think that the issues might be due to the way we use the serial devices in the java side. Cannot be 100% sure but I do see that

modbus binding does use “receive threshold” which should apparently make the serial input stream read operation blocking. If it is not blocking, the read() operation returns -1 (EOF).
receiveTimeout was used only with RTU modbus
quite many other openhab serial bindings set the receiveThreshold

I’ve now made sure the modbus binding calls m_CommPort.enableReceiveThreshold(1) before read(). In addition, timeout now applies to all transports. Finally, logging has been improved further.

The configuration of timeout is done with the connection key in openhab.cfg. In addition to to the old parameters:

devicePort (mandatory)
baudRate (optional)
dataBits
parity
stopBits
encoding

You can now configure:

timeout (in milliseconds)
flowControlIn
flowControlOut

For example, serial connection with 1000ms (=1sec) timeout
modbus:serial.slave2.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000

The timeout has been made configurable, useful at least for this testing phase.

@mbs38 @Ferryb4 Can you please try out again with this new version:
https://github.com/ssalonen/openhab/files/129697/org.openhab.binding.modbus-1.9.0-SNAPSHOT-pooling_serial_fixes_20160214_98b5a32.zip (modbus-pooling-test-version2 tag in my github repository)

To make the testing easier, please

have an minimal configuration (for example two slaves that just read data)
TRACE level logging enabled
reasonable timeout configured for all slaves. Please use exactly the same baud, parity, dataBits, stopBits, encoding and timeout if the port name is the same. Otherwise the connection is not shared and simultaneous requests are executed on the same serial device. Make sure timeout is smaller than the modbus poll period.
latest release version of openhab

When you have issues, please

paste the logs here (or even better use pastebin.com for long logs to make this thread more readable)
the associated openhab.cfg configuration
openhab item definitions.
modbus device you are using, and related devices (gateways etc)
standard you use for serial communication, e.g. RS-232 (based on the comments in the code, RS-485 might not work yet due to echo handling – we should make this configurable as well)

Best,
Sami

Ferryb4 · February 14, 2016, 3:35pm

Hi ssalonen,

I installed the new binding on my RPI. The log files are here.

Items

Group All

    /*Modbus*/
    Group Modbus_1 "Diepvries" (All)


    Number MB_1_05 "Voltage [%.1f Volt]" (Modbus_1){modbus="slave5:0"}

    /*Modbus_2*/
    Group Modbus_2 "Diepvries" (All)

    Number MB_2_05 "Voltage [%.1f Volt]" (Modbus_2){modbus="slave25:0"}

Config

############################### Modbus Binding ########################################
#
#
modbus:poll=10000
# Voltage
modbus:serial.slave5.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000
modbus:serial.slave5.id=1
modbus:serial.slave5.start=8192
modbus:serial.slave5.length=2
modbus:serial.slave5.type=holding
modbus:serial.slave5.valuetype=float32

# Voltage
modbus:serial.slave25.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000
modbus:serial.slave25.id=2
modbus:serial.slave25.start=8192
modbus:serial.slave25.length=2
modbus:serial.slave25.type=holding
modbus:serial.slave25.valuetype=float32

I use a RPi 2 with a RB-RS485 .
On my bus are two energy meters connected from Inepro PRO1 - MID - Modbus.

The Registers can you find here.

mbs38 · February 14, 2016, 6:31pm

Hi ssalonen,

I’ve tried it with the following config:

modbus:poll=200

modbus:serial.agsBus16Registers.connection=/dev/ttyS0:38400:8:none:1:rtu:100
modbus:serial.agsBus16Registers.id=16
modbus:serial.agsBus16Registers.start=0
modbus:serial.agsBus16Registers.length=2
modbus:serial.agsBus16Registers.type=input
modbus:serial.agsBus16Registers.valuetype=int16

modbus:serial.agsBus17Discretes.connection=/dev/ttyS0:38400:8:none:1:rtu:100
modbus:serial.agsBus17Discretes.id=17
modbus:serial.agsBus17Discretes.start=0
modbus:serial.agsBus17Discretes.length=1
modbus:serial.agsBus17Discretes.type=discrete

items:
Number agsBus16InputRegister1 “bus voltage: [%d mV]”{ modbus=“agsBus16Registers:1” }
Number agsBus16InputRegister0 “supply output voltage [%d mV]” { modbus=“agsBus16Registers:0” }
Contact agsBus17Discrete { modbus=“agsBus17Discretes:0” }

Here are the logs: http://pastebin.com/tQabp3iG

I am using a Modbus router that acts as a RS232 to RS485 converter => there are no echos.
Btw: Most USB to RS485 converters have the TXen and RXen pins of their RS485 line transceiver tied together, which means that they cannot receive while they are sending. So usually there won’t be any echos even though it’s RS485 (!). We need to make surethat nobody gets confused about this

[quote=“ssalonen, post:31, topic:5246”]
The timeout has been made configurable, useful at least for this testing phase.
[/quote] This has already proven to be a useful feature. By lowering the timeout, I was able to improve the performance significantly - however the errors persist…

[quote=“ssalonen, post:31, topic:5246”]
Make sure timeout is smaller than the modbus poll period.
[/quote] Why? In order to achieve the highest possible polling rate we want the modbus poll period to be 0ms. (meaning that once you’re finished with all devices, start again from the beginning and do not wait X milliseconds)

ssalonen · February 14, 2016, 7:52pm

thank you both @mbs38 and @Ferryb4. I shall look the logs…

@mbs38, I can’t see any errors in the logs? Did you paste it fully? I do see some state updates, so it’s working better? Or do the errors come only with more slaves?

In order to achieve the highest possible polling rate we want the modbus poll period to be 0ms. (meaning that once you’re finished with all devices, start again from the beginning and do not wait X milliseconds)

Yes, I do get this. With large timeout this would block the “0ms polling” since even one “timeout” might block the normal fast loop. Not sure if this happens often though and what would be the case…

Btw: Most USB to RS485 converters have the TXen and RXen pins of their RS485 line transceiver tied together, which means that they cannot receive while they are sending. So usually there won’t be any echos even though it’s RS485 (!). We need to make surethat nobody gets confused about this

Thanks for explaining this, did not know this. That’s good then, so that should not be an issue.

mbs38 · February 14, 2016, 8:38pm

For some reason I’m not getting any errors if start openhab by running start_debug.sh but I get tons of errors when running start.sh

I need to dig into my logging setup.

ssalonen · February 14, 2016, 9:26pm

Ok that’s quite interesting. If you find out a logging configuration that works for you, perhaps @Ferryb4 could also use that. I was missing some DEBUG level log statements still, or then I just misread the code…

mbs38 · February 14, 2016, 9:43pm

I’ve tried it with more slaves and shorter timeout and polling settings:

Config: http://pastebin.com/2Hh1bbpn

Now I get errors:
Logs: http://pastebin.com/3qKk5sr0

mbs38 · February 14, 2016, 10:49pm

Ok now things are getting weird:
When I change this line in logback_debug.xml

logger name=“org.openhab.binding.modbus” level=“DEBUG”

to

logger name=“org.openhab.binding.modbus” level=“TRACE”

the performance is doubled (amount of successful master-slave transactions). The configuration remained the same ( http://pastebin.com/2Hh1bbpn ).

rossko57 · February 18, 2016, 8:47pm

I have broken my cheap chinese TCP gateway, but am able to try the updated binding with a RS-485 serial setup
Two slaves configured, both part of one real device:
modbus:serial.slave4R.connection=COM5:9600:8:none:1:rtu:1000
modbus:tcp.slave4R.id=40
modbus:tcp.slave4R.type=coil
modbus:tcp.slave4R.start=16
modbus:tcp.slave4R.length=4
modbus:serial.slave4I.connection=COM5:9600:8:none:1:rtu:1000
modbus:tcp.slave4I.id=40
modbus:tcp.slave4I.type=discrete
modbus:tcp.slave4I.start=32
modbus:tcp.slave4I.length=4

All seems to work fine, no errors reported. Randomly commanding coil items on and off (so as to intersperse traffic with polls) doesn’t seem to cause issues.

ssalonen · February 19, 2016, 5:49am

Glad to hear it! If you don’t mind, can you please test it with the released official version modbus binding as well? Just to confirm that the new version fixes something

Thanks!

ssalonen · February 19, 2016, 6:49am

@mbs38 @Ferryb4 Now I get it why some log statements are missing! We have to setup logger for net.wimpi.modbus (modbus library inside the binding) as well:

<logger name="org.openhab.binding.modbus" level="TRACE" />
<logger name="net.wimpi.modbus" level="TRACE" />

If you enable both of those loggers, you should be able to see useful summaries in logs.

lgeorgiev · February 19, 2016, 10:24am

Hi Have same problems with Modbus. Since 1.6 no any solutions for this problem. The main is pooling proccess not works correct. I try with TCP and RTU . Same problem. There is also problem with connection component, but this is not the main problem. Is there any idea for solvin the problem with pooling proccess? I have ~ 15 slaves and till now no any solutions. In general The Modbus binding not working and can be used only for testing of one slave on table. No any productions options.

ssalonen · February 19, 2016, 3:58pm

@lgeorgiev exactly, it has been an issue for a long time with binding. That’s the reason implementation discussed in this thread has been created.

Have you tried out with the version linked in this thread? If not, here’s the instructions I gave in other thread test with modbus tcp. I would recommend using modbus tcp, my feeling is that you avoid a lot of issues related to serial communication by using that. Please don’t hesitate to ask if something is clear.

Please also note the extended logging configuration instructions mentioned above by me.

I would be very grateful if you have time to test this with your setup and report back! Thanks.

ssalonen · February 19, 2016, 4:07pm

@mbs38 did the errors reduce with TRACE level logging? I’m thinking whether the few millisecond overhead caused by the extensive logging could reduce errors since serial line is in not so heavy use… Specifically device issues mentioned in issue 3537 might be related. As mentioned in the issue, the implementation has configuration parameter for arbitrary sleep before executing the modbus serial transaction, it’s just not exposed as configuration parameter (default is no sleep)

Also could you have to paste logs with the net.wimpi.modbus turned to debug level in logs. That should have log statements about successful executions (if some transaction has initially failed)

Thanks!

rossko57 · February 19, 2016, 8:36pm

@ssalonen - I guess my two-slave serial setup is no good test. Seems to work just as well with binding from 1.8.0 distrib package. Host is an elderly (slow) WinXP laptop and USB-485 adaptor, timing may be relevant,