EXICodec encoding time inconsistent

Question

EXICodec encoding time inconsistent

Alfa-Valor opened this issue a year ago · 10 comments

Using the ISO15118 library I have encountered an issue I cannot quite seem to resolve.

When I am running the software stack on an Ubuntu VM the timings for encoding and decoding appear very fast and smooth. However now using it on two embedded linux devices the performance has plummeted. I cannot quite figure out why.

I will provide some details here :

INFO 2023-10-11 12:12:31,824 - iso15118.shared.exi_codec (177): EXI Codec version: 1.55
INFO 2023-10-11 12:12:31,825 - iso15118.secc (31): Starting 15118 version: 0.23.3
INFO 2023-10-11 12:12:31,830 - iso15118.secc.comm_session_handler (231): Communication session handler started
INFO 2023-10-11 12:12:31,833 - iso15118.secc.transport.udp_server (136): UDP server socket ready
INFO 2023-10-11 12:12:31,838 - iso15118.secc.transport.udp_server (122): UDP server started at address FF02::1%eth1 and port 15118
DEBUG 2023-10-11 12:13:41,818 - iso15118.secc.transport.udp_server (157): Message received from ('fe80::d60f:b2ff:fe07:359b', 49206, 0, 7): 01fe9000000000021000
INFO 2023-10-11 12:13:41,819 - iso15118.secc.comm_session_handler (405): SDPRequest received: [Security: NO_TLS, Protocol: TCP]
INFO 2023-10-11 12:13:41,832 - iso15118.secc.transport.tcp_server (134): TCP server started at address fe80::58f4:c8ff:fec1:16ff%eth1 and port 57454
INFO 2023-10-11 12:13:41,835 - iso15118.secc.comm_session_handler (432): Sending SDPResponse: [ IP address: fe80::58f4:c8ff:fec1:16ff, Port: 57454 , Security: NO_TLS , Transport: TCP ]
INFO 2023-10-11 12:13:41,856 - iso15118.secc.transport.udp_server (200): UDP server has been paused.
INFO 2023-10-11 12:13:41,857 - iso15118.secc.comm_session_handler (280): TCP client connected, client address is ('fe80::d60f:b2ff:fe07:359b', 43670, 0, 7).
INFO 2023-10-11 12:13:41,858 - iso15118.shared.comm_session (347): Starting a new communication session
INFO 2023-10-11 12:13:41,859 - iso15118.shared.states (139): Entered state SupportedAppProtocol
DEBUG 2023-10-11 12:13:41,860 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:13:42,624 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolReq":{"AppProtocol":[{"ProtocolNamespace":"urn:iso:15118:2:2013:MsgDef","VersionNumberMajor":2,"VersionNumberMinor":0,"SchemaID":1,"Priority":1}]}}
INFO 2023-10-11 12:13:42,626 - iso15118.shared.comm_session (236): supportedAppProtocolReq received
INFO 2023-10-11 12:13:42,627 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolRes": {"ResponseCode": "OK_SuccessfulNegotiation", "SchemaID": 1}}
INFO 2023-10-11 12:13:42,643 - iso15118.shared.exificient_exi_codec (45): 0.014929771423339844 time taken for encode
INFO 2023-10-11 12:13:42,644 - iso15118.secc.states.sap_states (147): Chosen protocol: ISO_15118_2
INFO 2023-10-11 12:13:42,645 - iso15118.shared.comm_session (431): Sent supportedAppProtocolRes
INFO 2023-10-11 12:13:42,645 - iso15118.secc.controller.simulator (646): iso15118 state: SupportedAppProtocol
INFO 2023-10-11 12:13:42,646 - iso15118.shared.states (139): Entered state SessionSetup
DEBUG 2023-10-11 12:13:42,646 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:13:55,406 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message":{"Header":{"SessionID":"00"},"Body":{"SessionSetupReq":{"EVCCID":"D40FB207359B"}}}}
INFO 2023-10-11 12:13:55,408 - iso15118.shared.comm_session (236): SessionSetupReq received
INFO 2023-10-11 12:13:55,430 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message": {"Header": {"SessionID": "B5726ED93618445A"}, "Body": {"SessionSetupRes": {"ResponseCode": "OK_NewSessionEstablished", "EVSEID": "UK123E1234", "EVSETimeStamp": 1697026435}}}}
INFO 2023-10-11 12:13:57,962 - iso15118.shared.exificient_exi_codec (45): 2.5304505825042725 time taken for encode
INFO 2023-10-11 12:13:57,964 - iso15118.shared.comm_session (431): Sent SessionSetupRes
INFO 2023-10-11 12:13:57,965 - iso15118.secc.controller.simulator (646): iso15118 state: SessionSetup
INFO 2023-10-11 12:13:57,969 - iso15118.shared.states (139): Entered state ServiceDiscovery
DEBUG 2023-10-11 12:13:57,972 - iso15118.shared.states (143): Waiting for up to 60.0 s
INFO 2023-10-11 12:13:57,991 - iso15118.shared.comm_session (398): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds.
INFO 2023-10-11 12:13:57,996 - iso15118.shared.comm_session (402): Reason: TCP peer closed connection
INFO 2023-10-11 12:14:00,000 - iso15118.shared.comm_session (410): terminated the data link
INFO 2023-10-11 12:14:03,006 - iso15118.shared.comm_session (417): TCP connection closed to peer with address ('fe80::d60f:b2ff:fe07:359b', 43670, 0, 7)
WARNING 2023-10-11 12:14:03,007 - iso15118.secc.transport.tcp_server (149): Closing TCP server
INFO 2023-10-11 12:14:03,009 - iso15118.secc.transport.udp_server (208): UDP server has been resumed.
DEBUG 2023-10-11 12:14:03,115 - iso15118.secc.transport.udp_server (157): Message received from ('fe80::d60f:b2ff:fe07:359b', 49206, 0, 7): 01fe9000000000021000
INFO 2023-10-11 12:14:03,116 - iso15118.secc.comm_session_handler (405): SDPRequest received: [Security: NO_TLS, Protocol: TCP]
INFO 2023-10-11 12:14:03,129 - iso15118.secc.transport.tcp_server (134): TCP server started at address fe80::58f4:c8ff:fec1:16ff%eth1 and port 57454
INFO 2023-10-11 12:14:03,131 - iso15118.secc.comm_session_handler (432): Sending SDPResponse: [ IP address: fe80::58f4:c8ff:fec1:16ff, Port: 57454 , Security: NO_TLS , Transport: TCP ]
INFO 2023-10-11 12:14:03,163 - iso15118.secc.transport.udp_server (200): UDP server has been paused.
INFO 2023-10-11 12:14:03,165 - iso15118.secc.comm_session_handler (280): TCP client connected, client address is ('fe80::d60f:b2ff:fe07:359b', 43672, 0, 7).
INFO 2023-10-11 12:14:03,165 - iso15118.shared.comm_session (347): Starting a new communication session
INFO 2023-10-11 12:14:03,166 - iso15118.shared.states (139): Entered state SupportedAppProtocol
DEBUG 2023-10-11 12:14:03,166 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:14:03,299 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolReq":{"AppProtocol":[{"ProtocolNamespace":"urn:iso:15118:2:2013:MsgDef","VersionNumberMajor":2,"VersionNumberMinor":0,"SchemaID":1,"Priority":1}]}}
INFO 2023-10-11 12:14:03,300 - iso15118.shared.comm_session (236): supportedAppProtocolReq received
INFO 2023-10-11 12:14:03,302 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolRes": {"ResponseCode": "OK_SuccessfulNegotiation", "SchemaID": 1}}
INFO 2023-10-11 12:14:03,364 - iso15118.shared.exificient_exi_codec (45): 0.061188697814941406 time taken for encode
INFO 2023-10-11 12:14:03,366 - iso15118.secc.states.sap_states (147): Chosen protocol: ISO_15118_2
INFO 2023-10-11 12:14:03,368 - iso15118.shared.comm_session (431): Sent supportedAppProtocolRes
INFO 2023-10-11 12:14:03,372 - iso15118.secc.controller.simulator (646): iso15118 state: SupportedAppProtocol
INFO 2023-10-11 12:14:03,375 - iso15118.shared.states (139): Entered state SessionSetup
DEBUG 2023-10-11 12:14:03,377 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:14:09,073 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message":{"Header":{"SessionID":"00"},"Body":{"SessionSetupReq":{"EVCCID":"D40FB207359B"}}}}
INFO 2023-10-11 12:14:09,086 - iso15118.shared.comm_session (236): SessionSetupReq received
INFO 2023-10-11 12:14:09,108 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message": {"Header": {"SessionID": "AED5C79B03FB6F19"}, "Body": {"SessionSetupRes": {"ResponseCode": "OK_NewSessionEstablished", "EVSEID": "UK123E1234", "EVSETimeStamp": 1697026449}}}}
INFO 2023-10-11 12:14:12,053 - iso15118.shared.exificient_exi_codec (45): 2.9400177001953125 time taken for encode
INFO 2023-10-11 12:14:12,056 - iso15118.shared.comm_session (431): Sent SessionSetupRes
INFO 2023-10-11 12:14:12,056 - iso15118.secc.controller.simulator (646): iso15118 state: SessionSetup
INFO 2023-10-11 12:14:12,057 - iso15118.shared.states (139): Entered state ServiceDiscovery
DEBUG 2023-10-11 12:14:12,064 - iso15118.shared.states (143): Waiting for up to 60.0 s
INFO 2023-10-11 12:14:12,067 - iso15118.shared.comm_session (398): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds.
INFO 2023-10-11 12:14:12,068 - iso15118.shared.comm_session (402): Reason: TCP peer closed connection
INFO 2023-10-11 12:14:14,075 - iso15118.shared.comm_session (410): terminated the data link
INFO 2023-10-11 12:14:17,078 - iso15118.shared.comm_session (417): TCP connection closed to peer with address ('fe80::d60f:b2ff:fe07:359b', 43672, 0, 7)
WARNING 2023-10-11 12:14:17,079 - iso15118.secc.transport.tcp_server (149): Closing TCP server
INFO 2023-10-11 12:14:17,081 - iso15118.secc.transport.udp_server (208): UDP server has been resumed.
DEBUG 2023-10-11 12:14:17,143 - iso15118.secc.transport.udp_server (157): Message received from ('fe80::d60f:b2ff:fe07:359b', 49206, 0, 7): 01fe9000000000021000
INFO 2023-10-11 12:14:17,145 - iso15118.secc.comm_session_handler (405): SDPRequest received: [Security: NO_TLS, Protocol: TCP]
INFO 2023-10-11 12:14:17,152 - iso15118.secc.transport.tcp_server (134): TCP server started at address fe80::58f4:c8ff:fec1:16ff%eth1 and port 57454
INFO 2023-10-11 12:14:17,162 - iso15118.secc.comm_session_handler (432): Sending SDPResponse: [ IP address: fe80::58f4:c8ff:fec1:16ff, Port: 57454 , Security: NO_TLS , Transport: TCP ]
INFO 2023-10-11 12:14:17,185 - iso15118.secc.transport.udp_server (200): UDP server has been paused.
INFO 2023-10-11 12:14:17,187 - iso15118.secc.comm_session_handler (280): TCP client connected, client address is ('fe80::d60f:b2ff:fe07:359b', 43674, 0, 7).
INFO 2023-10-11 12:14:17,188 - iso15118.shared.comm_session (347): Starting a new communication session
INFO 2023-10-11 12:14:17,188 - iso15118.shared.states (139): Entered state SupportedAppProtocol
DEBUG 2023-10-11 12:14:17,189 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:14:17,252 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolReq":{"AppProtocol":[{"ProtocolNamespace":"urn:iso:15118:2:2013:MsgDef","VersionNumberMajor":2,"VersionNumberMinor":0,"SchemaID":1,"Priority":1}]}}
INFO 2023-10-11 12:14:17,254 - iso15118.shared.comm_session (236): supportedAppProtocolReq received
INFO 2023-10-11 12:14:17,256 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolRes": {"ResponseCode": "OK_SuccessfulNegotiation", "SchemaID": 1}}
INFO 2023-10-11 12:14:17,268 - iso15118.shared.exificient_exi_codec (45): 0.011466741561889648 time taken for encode
INFO 2023-10-11 12:14:17,271 - iso15118.secc.states.sap_states (147): Chosen protocol: ISO_15118_2
INFO 2023-10-11 12:14:17,272 - iso15118.shared.comm_session (431): Sent supportedAppProtocolRes
INFO 2023-10-11 12:14:17,273 - iso15118.secc.controller.simulator (646): iso15118 state: SupportedAppProtocol
INFO 2023-10-11 12:14:17,275 - iso15118.shared.states (139): Entered state SessionSetup
DEBUG 2023-10-11 12:14:17,276 - iso15118.shared.states (143): Waiting for up to 20.0 s
INFO 2023-10-11 12:14:20,418 - iso15118.shared.exi_codec (304): Decoded message (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message":{"Header":{"SessionID":"00"},"Body":{"SessionSetupReq":{"EVCCID":"D40FB207359B"}}}}
INFO 2023-10-11 12:14:20,424 - iso15118.shared.comm_session (236): SessionSetupReq received
INFO 2023-10-11 12:14:20,434 - iso15118.shared.exi_codec (248): Message to encode (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message": {"Header": {"SessionID": "6C141611E24FF08C"}, "Body": {"SessionSetupRes": {"ResponseCode": "OK_NewSessionEstablished", "EVSEID": "UK123E1234", "EVSETimeStamp": 1697026460}}}}
INFO 2023-10-11 12:14:22,698 - iso15118.shared.exificient_exi_codec (45): 2.2585692405700684 time taken for encode
INFO 2023-10-11 12:14:22,711 - iso15118.shared.comm_session (431): Sent SessionSetupRes
INFO 2023-10-11 12:14:22,712 - iso15118.secc.controller.simulator (646): iso15118 state: SessionSetup
INFO 2023-10-11 12:14:22,713 - iso15118.shared.states (139): Entered state ServiceDiscovery
DEBUG 2023-10-11 12:14:22,713 - iso15118.shared.states (143): Waiting for up to 60.0 s
INFO 2023-10-11 12:14:25,880 - iso15118.shared.comm_session (398): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds.
INFO 2023-10-11 12:14:25,881 - iso15118.shared.comm_session (402): Reason: TCP peer closed connection
INFO 2023-10-11 12:14:27,883 - iso15118.shared.comm_session (410): terminated the data link
WARNING 2023-10-11 12:14:29,609 - iso15118.secc.transport.tcp_server (149): Closing TCP server

Output of the program. I have added several "time to encode" stamps these are in seconds. I am simply running both of the simulators. (EVCC and SECC). I this case it is the SECC.

The system it is running on should have the capacity in processing power to handle this.

Architecture: aarch64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 4
On-line CPU(s) list: 0,1
Off-line CPU(s) list: 2,3
Vendor ID: ARM
Model name: Cortex-A53
Model: 4
Thread(s) per core: 1
Core(s) per cluster: 2
Socket(s): -
Cluster(s): 1
Stepping: r0p4
CPU max MHz: 1400.0000
CPU min MHz: 1200.0000
BogoMIPS: 16.00
Flags: fp asimd evtstrm aes pmull sha1 sha2 crc32 cpuid

Small note : I have modified the launch_gateway function to supply py4j with a set path JDK on an SD card because of storage space restrictions

        self.gateway = JavaGateway.launch_gateway(
            classpath=JAR_FILE_PATH,
            die_on_exit=True,
            java_path="/data/jdk-17.0.8.1+1/bin/java",
            javaopts=["--add-opens", "java.base/java.lang=ALL-UNNAMED"],
        )

ref: iso15118/shared/exificient_exi_codec.py 29/66

Has anyone expierenced similar issues to mine? If any more info is required I will supply it.

Answer 1 · 2023-10-12T13:28:37.000Z

Hi, we have experienced a drop in performance with embedded devices in comparison to general-purpose CPUs. The java engine is quite heavy for embedded applications and is not suitable to run the codec.
We have a rust codec, available only with our Josev Pro version, tailored for embedded applications where the performance is not an issue.

Answer 2 · 2023-10-12T13:28:49.000Z

Hi, we have experienced a drop in performance with embedded devices in comparison to general-purpose CPUs. The java engine is quite heavy for embedded applications and is not suitable to run the codec.
We have a rust codec, available only with our Josev Pro version, tailored for embedded applications where the performance is not an issue.

Answer 3 · 2023-10-13T06:43:30.000Z

Then may I ask why the Supported app protocol encodes in such a swift time yet the other messages take such an extremely long time? It just doesn't make much sense to me why that message is encoded so fast while the others aren't. Thank you.

Answer 4 · 2023-10-13T09:05:20.000Z

One reason could be because of the schema used to generate the EXI. The schema used for supportedAppProtocol is the V2G_CI_AppProtocol.xsd which is the simplest of the lot and is that single file. So a lot less grammar to traverse. Also, supportedProtocolRes afaik is the shortest EXI stream of all EXI messages in 15118-2.
Setting MESSAGE_LOG_EXI=True in the env would show this.
Majority of the other -2 messages requires traversing multiple schema files starting from V2G_CI_MsgDef.xsd and therefore a larger grammar file.

Answer 5 · 2023-10-13T09:39:16.000Z

Can I ask you if you tried to set MESSAGE_LOG_EXI=False and LOG_LEVEL=INFO and check if the timings improve?
logging is very expensive, consuming a lot of MCU time

Answer 6 · 2023-10-17T07:53:27.000Z

I will try, thank you! I will post results

Cheers.

Apologies for the late response.

Answer 7 · 2023-10-17T08:17:26.000Z

Alright, disabling both JSON and EXI logging has improved performance quite a bit.

I have additionally cranked up the OS niceness for the EVCC and SECC and enabled TCP_NODELAY for the SECC socket. It still however times out occasionally in the beginning. Performance has greatly improved though.

One thing I have also noted, the more cycles that run sequentially, the more the performance of the codec appears to improve. I can for example set the SDP retry cycles of the EVCC to around 50. and the longer it runs the more the performance of the codec appears to improve with the occasional outlier.

Perhaps I will also look into maybe improving the performance of the codec on the system myself by looking for optimizations, although I doubt I will find many.

If you have any other ideas for improving the performance I would love to hear them!

Answer 8 · 2023-10-17T09:12:33.000Z

One reason could be because of the schema used to generate the EXI. The schema used for supportedAppProtocol is the V2G_CI_AppProtocol.xsd which is the simplest of the lot and is that single file. So a lot less grammar to traverse. Also, supportedProtocolRes afaik is the shortest EXI stream of all EXI messages in 15118-2. Setting MESSAGE_LOG_EXI=True in the env would show this. Majority of the other -2 messages requires traversing multiple schema files starting from V2G_CI_MsgDef.xsd and therefore a larger grammar file.

I do not believe I know quite enough about the library, however I feel it is still worth asking.

Could it be that the performance of supported app protocol is fast because it doesnt have to import very big XML files. The path for a regular message goes something like this.

<xs:import namespace="urn:iso:15118:2:2013:MsgHeader" schemaLocation="V2G_CI_MsgHeader.xsd"/> | 20 lines
<xs:import namespace="urn:iso:15118:2:2013:MsgBody" schemaLocation="V2G_CI_MsgBody.xsd"/> | 499 lines
MsgDef.xsd

<xs:import namespace="urn:iso:15118:2:2013:MsgDataTypes" schemaLocation="V2G_CI_MsgDataTypes.xsd"/> | 723 lines
<xs:import namespace="http://www.w3.org/2000/09/xmldsig#" schemaLocation="../xmldsig-core-schema.xsd"/> | 319 lines
MsgHeader.xsd

<xs:import namespace="urn:iso:15118:2:2013:MsgDataTypes" schemaLocation="V2G_CI_MsgDataTypes.xsd"/> | 723 lines
MsgBody.xsd

Is this import chain called every time a message needs to be constructed? Or is it built once and cached? Reconstructing a message by hand "ex. SessionSetupReq" results in a decently small fille.

I may be wrong about this, or maybe it is optimized away later but I am just trying to understand if there is maybe a better way to do this, like defining the message attributes in individual files and calling them when required.

Again, I may be wrong about this so please correct me if I am wrong.
@shalinnijel2

{"supportedAppProtocolRes": {"ResponseCode": "OK_SuccessfulNegotiation", "SchemaID": 1}}
0.022307395935058594 time taken for encode

{"SessionSetupRes": {"Header": {"SessionID": "3A6E3641D2A37E00", "TimeStamp": 1697535229}, "ResponseCode": "OK_NewSessionEstablished", "EVSEID": "UK123E1234"}}
1.482891321182251 time taken for encode

The difference in length of message shouldnt matter that much

Answer 9 · 2023-11-02T17:50:26.000Z

Could it be that the performance of supported app protocol is fast because it doesnt have to import very big XML files.

Yes, the grammar for AppProtocol is way smaller compared to the others. The grammar is loaded only once. So I would expect the subsequent calls to be quicker.

The difference in length of message shouldnt matter that much

Correct - Length of the input does have an impact, but the size of the grammar has the bigger impact.

As a quick test, could you try the following please - construct an standalone SessionSetupReq(or another message that requires V2GCI_Msg_Def with random values) before running the actual session. Would like to see if this helps with your case.

Answer 10 · 2023-11-06T12:53:18.000Z

I stripped away all message info related to other messages except for SessionSetup in the messages, however the session is still somehow running the simulated session in its entirety which is impressive.

I speculate that the .jar is loading these files statically internally and any changes I make are not doing anything.

Could this be true?

@shalinnijel2