[etherlab-dev] Bus scan takes long time at low rates

[Steffen Dalgard]

Hi,
I am setting up a environment for development an test.
In order to make it easy to replicate at different sites it is running in a
virtual machine inside Oracle VM VirtualBox Manager.
The EtherCAT slaves are connected to a dedicated bridged interface using
the generic Ethernet driver.
As you understand this is not a high performance system.

Before activating the master it takes below 1 sec for scanning the bus with
5 slaves.
When starting the userspace application and activating the master for
cyclic operation the rescan take very long time. It seems that the rescan
gets slower when cycle time are long. In my application I am using 10HZ
cycle time.
In the attached logs the time for scanning is about 3 minutes.
During the rescan period the processor load increase significantly (* 20)
but the packets on the bus stays constant at 10 packets pr. sec.

Anyone having experience how to reduce time for scanning?

I can reduce the cycle time downto 100HZ but the scan time is still long.
A downside is that I get more timeout / unmatched packets.

Anyone having ideas what causing packet loss?

The virtual machine is running
Linux 10.04 LTS
gcc (Ubuntu 4.4.3-4ubuntu5.1) 4.4.3 is used for compilation
I have attached three logs showing syslog output

More details and examples can be added if needed.

Any comments welcome.

Best regards
Steffen Dalgard
SINTEF ICT
Norway


"SYSLOG messages when starting up Master"
Apr 30 09:29:09 ecmaster-vm kernel: [86526.177110] EtherCAT: Master driver
1.5.1 41dc9a4a0f76
Apr 30 09:29:09 ecmaster-vm kernel: [86526.178626] EtherCAT: 1 master
waiting for devices.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.184362] ec_generic: EtherCAT
master generic Ethernet device module 1.5.1 41dc9a4a0f76
Apr 30 09:29:09 ecmaster-vm kernel: [86526.184375] EtherCAT: Accepting
08:00:27:BF:57:AC as main device for master 0.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.184391] EtherCAT 0: Starting
EtherCAT-IDLE thread.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.184423] EtherCAT 0: Link state
of ecm0 changed to UP.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.188311] EtherCAT 0: 5 slave(s)
responding on main device.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.188315] EtherCAT 0: Slave states
on main device: PREOP.
Apr 30 09:29:09 ecmaster-vm kernel: [86526.193124] EtherCAT 0: Scanning bus.
Apr 30 09:29:10 ecmaster-vm kernel: [86526.774874] EtherCAT 0: Bus scanning
completed in 580 ms.
Apr 30 09:29:10 ecmaster-vm kernel: [86526.774879] EtherCAT 0: Using slave
0 as DC reference clock.
Apr 30 09:31:20 ecmaster-vm kernel: [86656.548051] EtherCAT WARNING 0: 1
datagram TIMED OUT!
Apr 30 09:35:17 ecmaster-vm kernel: [86894.412791] EtherCAT WARNING 0: 1
datagram TIMED OUT!
Apr 30 09:35:17 ecmaster-vm kernel: [86894.412811] EtherCAT WARNING 0: 1
datagram UNMATCHED!
Apr 30 09:36:04 ecmaster-vm kernel: [86940.780824] EtherCAT WARNING 0: 2
datagrams TIMED OUT!
Apr 30 09:36:04 ecmaster-vm kernel: [86940.780842] EtherCAT WARNING 0: 2
datagrams UNMATCHED!

"SYSLOG messages when starting application"
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284019] EtherCAT: Requesting
master 0...
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284231] EtherCAT: Successfully
requested master 0.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284279] EtherCAT 0: Domain0:
Logical address 0x00000000, 2 byte, expected working counter 3.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284284] EtherCAT 0:   Datagram
domain0-0-main: Logical offset 0x00000000, 2 byte, type LRW.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284287] EtherCAT 0: Domain1:
Logical address 0x00000002, 0 byte, expected working counter 0.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284668] EtherCAT 0: Master
thread exited.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.284671] EtherCAT 0: Starting
EtherCAT-OP thread.
Apr 30 09:38:49 ecmaster-vm kernel: [87106.285073] EtherCAT WARNING 0: 1
datagram UNMATCHED!
Apr 30 09:38:56 ecmaster-vm kernel: [87113.384968] EtherCAT 0: Domain 0:
Working counter changed to 2/3 (2+0).
Apr 30 09:38:59 ecmaster-vm kernel: [87116.386563] EtherCAT 0: Domain 0:
Working counter changed to 3/3 (3+0).
Apr 30 09:39:00 ecmaster-vm kernel: [87117.288055] EtherCAT 0: Slave states
on main device: PREOP, OP.


"SYSLOG messages when forcing bus rescan by extracting and inserting one of
the slaves"
Apr 30 09:41:25 ecmaster-vm kernel: [87261.585150] EtherCAT 0: Domain 0:
Working counter changed to 2/3 (2+0).
Apr 30 09:41:25 ecmaster-vm kernel: [87261.585644] EtherCAT 0: 4 slave(s)
responding on main device.
Apr 30 09:41:25 ecmaster-vm kernel: [87262.085167] EtherCAT 0: Scanning bus.
Apr 30 09:44:02 ecmaster-vm kernel: [87418.885938] EtherCAT 0: Bus scanning
completed in 157196 ms.
Apr 30 09:44:02 ecmaster-vm kernel: [87418.885953] EtherCAT 0: Using slave
0 as DC reference clock.
Apr 30 09:44:04 ecmaster-vm kernel: [87420.685695] EtherCAT 0: 5 slave(s)
responding on main device.
Apr 30 09:44:04 ecmaster-vm kernel: [87420.685710] EtherCAT 0: Slave states
on main device: INIT, PREOP, OP.
Apr 30 09:44:04 ecmaster-vm kernel: [87421.185114] EtherCAT 0: Scanning bus.
Apr 30 09:47:25 ecmaster-vm kernel: [87621.985808] EtherCAT 0: Bus scanning
completed in 201196 ms.
Apr 30 09:47:25 ecmaster-vm kernel: [87621.985825] EtherCAT 0: Using slave
0 as DC reference clock.
Apr 30 09:47:30 ecmaster-vm kernel: [87627.184968] EtherCAT 0: Domain 0:
Working counter changed to 3/3 (3+0).
Apr 30 09:47:31 ecmaster-vm kernel: [87628.088202] EtherCAT 0: Slave states
on main device: PREOP, OP.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.etherlab.org/pipermail/etherlab-dev/attachments/20130430/bd4b7e1a/attachment.htm>