Robot Keyword Run Extra Slow

Hi Robot, I am experiencing some robot test issues on docker. The test suites need about more than 4 hours, from time to time some cases failed due to keyword run over longer than normal needs. For example: Get Random to generate a random number, here its definition: def get_random(self): return random.randint(1,math.pow(2,31))

Here is one its result: KEYWORD ${hth} = HSSRammbock . Get Random Start / End / Elapsed: 20190918 16:18:10.885 / 20190918 16:18:33.960 / 00:00:23.075 16:18:33.960 INFO ${hth} = 1758648145 00:00:00.003KEYWORD ${ete} = HSSRammbock . Get Random Start / End / Elapsed: 20190918 16:18:33.961 / 20190918 16:18:33.964 / 00:00:00.003 16:18:33.962 INFO ${ete} = 1706015997

The run time over long happened randomly on any keyword and hard to reproduced. The following is another case with strace log: 344 23:12:30.986453 write(1, "Charging.EPC-26086 MSCC Requirements.EPC-58207.EPC-58434 :: Verify if in CD...\n", 79) = 79 <0.000051> 344 23:12:30.986608 write(1, "==============================================================================\n", 79) = 79 <0.000034> 344 23:12:30.986946 open("/tmp/s1.starttime", O_WRONLY|O_CREAT|O_APPEND, 0666) = 10</tmp/s1.starttime> <0.000044> 344 23:12:30.987050 lseek(10</tmp/s1.starttime>, 0, SEEK_END) = 4426 <0.000015> 344 23:12:30.987107 fstat(10</tmp/s1.starttime>, {st_dev=makedev(0, 60), st_ino=2885016, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=16, st_size=4426, st_atime=2019/09/30-17:21:07.109000000, st_mtime=2019/10/02-23:12:30.072000000, st_ctime=2019/10/02-23:12:30.072000000}) = 0 <0.000015> 344 23:12:30.987209 fstat(10</tmp/s1.starttime>, {st_dev=makedev(0, 60), st_ino=2885016, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=16, st_size=4426, st_atime=2019/09/30-17:21:07.109000000, st_mtime=2019/10/02-23:12:30.072000000, st_ctime=2019/10/02-23:12:30.072000000}) = 0 <0.000016> 344 23:12:30.987294 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f50f1cd6000 <0.000017> 344 23:12:30.987354 write(10</tmp/s1.starttime>, "EPC-58434: 20191002 23:12:30.725\n", 33) = 33 <0.000020> 344 23:12:30.987419 close(10</tmp/s1.starttime>) = 0 <0.000017> 344 23:12:30.987474 munmap(0x7f50f1cd6000, 4096) = 0 <0.000022> 344 23:12:30.999728 stat("/etc/localtime", {st_dev=makedev(0, 60), st_ino=1054970, st_mode=S_IFREG|0644, st_nlink=6, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=118, st_atime=2017/03/02-15:01:37, st_mtime=2017/03/02-15:01:37, st_ctime=2019/09/18-12:55:05.586000000}) = 0 <0.000024> 344 23:12:31.001988 write(3</opt/sps/spstests/ChargingRegressionSuite/fixOutput00.xml>, "\n\n<test id=\"s1-s4-s13-s4-t17\" name=\"Delete Counter\">\n\nCharging183\nCharging_Sanity\nCHARGING_TESTS\nCounters\ncsl_gsinghgu\nDecentralized Charging\nIEC\nMultiM"..., 8193) = 8193 <0.000034> 344 23:12:31.024038 write(3</opt/sps/spstests/ChargingRegressionSuite/fixOutput00.xml>, "\narg>@{varargs}</arg\n\n<kw name=\"Get Length\" library=\"BuiltIn\">\nReturns and logs the length of the given item as an integer.\n\n${varargs}\n\n\n${intf_count}\n\n<msg timestamp=\""..., 8205) = 8205 <0.000031> 344 23:12:31.057250 write(3</opt/sps/spstests/ChargingRegressionSuite/fixOutput00.xml>, "${ete} = 27141405\n<status status=\"PASS\" endtime=\"20191002 23:12:31.024\" starttime=\"20191002 23:12:31.024\">\n\n<kw name=\"Set Variable If\" library=\"BuiltIn\">\nSets variable based on the given condition.\n\n${command-"..., 8194) = 8194 <0.000036> 344 23:12:31.065175 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f500fc00000 <0.000025> 344 23:12:31.074836 write(3</opt/sps/spstests/ChargingRegressionSuite/fixOutput00.xml>, "\n\n<status status=\"PASS\" endtime=\"20191002 23:12:31.058\" starttime=\"20191002 23:12:31.057\">\n\n<kw name=\"Set Variable\" library=\"BuiltIn\">\nReturns the given values which can then be assigned to a variables.\n<arguments"..., 8273) = 8273 <0.000039> 354 23:12:31.082644 <... poll resumed> ) = 0 (Timeout) <0.100147> 354 23:12:31.082697 futex(0x218b720, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...> 359 23:12:31.083015 <... poll resumed> ) = 0 (Timeout) <0.100144> 359 23:12:31.083060 futex(0x218b720, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...> 357 23:12:31.083192 <... poll resumed> ) = 0 (Timeout) <0.100143> 357 23:12:31.083237 futex(0x218b720, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...> 461 23:12:31.083985 <... poll resumed> ) = 0 (Timeout) <0.100133> 461 23:12:31.084039 futex(0x218b720, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...> 356 23:12:31.380658 <... select resumed> ) = 0 (Timeout) <0.500557> 356 23:12:31.380746 futex(0x218b720, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...> 344 23:12:39.446342 munmap(0x7f50bf1ff000, 262144) = 0 <0.000057> 344 23:12:39.448915 munmap(0x7f50bf67f000, 262144) = 0 <0.000044> 344 23:12:39.454284 munmap(0x7f50c0a3f000, 262144) = 0 <0.000051> 344 23:12:39.457604 munmap(0x7f50c103f000, 262144) = 0 <0.000048> 344 23:12:39.458019 munmap(0x7f50c10bf000, 262144) = 0 <0.000046> 344 23:12:39.459616 munmap(0x7f50c12ff000, 262144) = 0 <0.000045> 344 23:12:39.460083 munmap(0x7f50c137f000, 262144) = 0 <0.000057>

Currently the test suite EPC-58434 is running. But the following line are for previous suite EPC-58342: 344 23:12:31.001988 write(3</opt/sps/spstests/ChargingRegressionSuite/fixOutput00.xml>, "\n\n\n\nCharging183\nCharging_Sanity\nCHARGING_TESTS\nCounters\ncsl_gsinghgu\nDecentralized Charging\nIEC\nMultiM"..., 8193) = 8193 <0.000034>

From 23:12:31.380746, there is more than 8 seconds lost. Could we identify why there is 8 seconds gap? and how to avoid it?

over_long_strace.txt

ombre42 / robotframework-sudslibrary

Robot Keyword Run Extra Slow #33