Issues with SpiNNaker setup and run in custom simulation environment


#1

Dear SpiNNaker community,

I am using the SpiNN-3 board to run experiments in real time in a custom simulation environment of the Human Brain Project. I am able to successfully connect to the board and establish the UDP connection.
Since the simulation should run in real time, the time_scale_factor in the config file of my home directory (.spynnaker.cfg) is set to 1 and use a timestep of 1ms for the SpiNNaker simulation.

However, the simulation runs far off real time, taking even more than a second to run one SpiNNaker simulation loop. The logs of the simulation show, that there are some actions taking rather long and might be the reason behind this:

[spinn_front_end_common.interface.abstract_spinnaker_base][INFO] 2018-12-13 16:24:51,438: Run 1 of 1
clearing IOBUF from the machine
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:51,535: Time 0:00:00.001747 taken by ChipIOBufClearer
Reloading data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:51,537: Time 0:00:00.001538 taken by DSGRegionReloader
Updating run time
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:51,550: Time 0:00:00.012639 taken by ChipRuntimeUpdater
Creating database
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:53,482: Time 0:00:01.931568 taken by DatabaseInterface
UDPConnection init 0
127.0.0.1
UDPConnection init 1
50493
UDPConnection init 0
127.0.0.1
UDPConnection init 1
59672
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:53,484: Time 0:00:00.001365 taken by NotificationProtocol
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:53,484: ** Notifying external sources that the database is ready for reading **
[spinn_front_end_common.interface.interface_functions.application_runner][INFO] 2018-12-13 16:24:53,484: *** Running simulation... *** 
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:53,485: 0.0.0.0:19999 Reading database
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:53,485: 0.0.0.0:19996 Reading database
******************_handle_possible_rerun_state 0*****************
******************_handle_possible_rerun_state 1*****************
45244
<socket._socketobject object at 0x7fd6b44f7a60>******************_handle_possible_rerun_state 0*****************

1******************_handle_possible_rerun_state 2*****************

17895
17895
<socket._socketobject object at 0x7fd6b45741a0>
1
******************_handle_possible_rerun_state 3*****************
17895
UDPConnection init 0
0.0.0.0
UDPConnection init 1
55192
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:53,487: Notifying the toolchain that the database has been read
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:53,487: Waiting for message to indicate that the simulation has started or resumed
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:53,487: ** Confirmation from 127.0.0.1:19999 received, continuing **
Loading buffers (0 bytes)
|0%                          50%                         100%|
 ============================================================
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:53,527: ** Awaiting for a response from an external source to state its ready for the simulation to start **
UDPConnection init 0
0.0.0.0
UDPConnection init 1
17895
EIEIOConnection __repr__
[spinn_front_end_common.utilities.connections.live_event_connection][INFO] 2018-12-13 16:24:54,218: Listening for traffic from right on 0.0.0.0:17895
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,219: Notifying the toolchain that the database has been read
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,219: Waiting for message to indicate that the simulation has started or resumed
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:54,219: ** Confirmation from 127.0.0.1:19996 received, continuing **
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:54,318: ** Sending start / resume message to external sources to state the simulation has started or resumed. **
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:54,320: ** Awaiting for a response from an external source to state its ready for the simulation to start **
SpyNNakerDatabaseConnection:0.0.0.0:19999: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, initial daemon)>.start(): starting thread
start_resume callback thread for live_event_connection 19999:0.0.0.0: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, started daemon 140559079421696)>.__bootstrap(): thread started
start_resume callback thread for live_event_connection 19999:0.0.0.0: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, started daemon 140559079421696)>.__bootstrap(): normal return
SpyNNakerDatabaseConnection:0.0.0.0:19999: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, initial daemon)>.start(): starting thread
start_resume callback thread for live_event_connection 19999:0.0.0.0: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, started daemon 140559079421696)>.__bootstrap(): thread started
start_resume callback thread for live_event_connection 19999:0.0.0.0: <Thread(start_resume callback thread for live_event_connection 19999:0.0.0.0, started daemon 140559079421696)>.__bootstrap(): normal return
[spinn_front_end_common.interface.interface_functions.application_runner][INFO] 2018-12-13 16:24:54,323: Application started; waiting 1.1s for it to stop
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,324: Waiting for message to indicate that the simulation has stopped or paused
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,324: Waiting for message to indicate that the simulation has stopped or paused
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:55,446: ** Sending pause / stop message to external sources to state the simulation has been paused or stopped. **
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,446: Time 0:00:01.961778 taken by ApplicationRunner
Extracting buffers from the last run
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,453: Time 0:00:00.007090 taken by BufferExtractor
Getting provenance data from machine graph
|0%                          50%                         100%|
 ============================================================
Getting provenance data from application graph
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,456: Time 0:00:00.002037 taken by GraphProvenanceGatherer
Getting provenance data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,463: Time 0:00:00.007172 taken by PlacementsProvenanceGatherer
Getting Router Provenance
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,468: Time 0:00:00.003780 taken by RouterProvenanceGatherer
Getting profile data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:55,472: Time 0:00:00.003943 taken by ProfileDataGatherer
_write_provenance

The conspicuous logs here are (at least it seems for me they are causing the issues):

Creating database
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-13 16:24:53,482: Time 0:00:01.931568 taken by DatabaseInterface

which takes almost 2 seconds, and

[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:53,527: ** Awaiting for a response from an external source to state its ready for the simulation to start **
UDPConnection init 0
0.0.0.0
UDPConnection init 1
17895
EIEIOConnection __repr__
[spinn_front_end_common.utilities.connections.live_event_connection][INFO] 2018-12-13 16:24:54,218: Listening for traffic from right on 0.0.0.0:17895

which takes again almost 1 second (comparing the time the logs are printed), as well as

[spinn_front_end_common.interface.interface_functions.application_runner][INFO] 2018-12-13 16:24:54,323: Application started; waiting 1.1s for it to stop
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,324: Waiting for message to indicate that the simulation has stopped or paused
[spinn_front_end_common.utilities.database.database_connection][INFO] 2018-12-13 16:24:54,324: Waiting for message to indicate that the simulation has stopped or paused
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-13 16:24:55,446: ** Sending pause / stop message to external sources to state the simulation has been paused or stopped. **

which explicitly states the simulation is waiting over 1 second for the application to stop.

[EDIT/]:
I figured out how to stop the simulation from creating a database, by adding the following lines to the bottom of the .spynnaker.cfg file, which speeds up the simulation tremendously:

create_database = False
wait_on_confirmation = False
create_routing_info_to_neuron_id_mapping = False 

However, I receive multiple errors similar to the following one:

Exception in thread SpyNNakerDatabaseConnection:0.0.0.0:19996:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/home/dyck/Documents/NRP/spinnaker/SpiNNFrontEndCommon/spinn_front_end_common/utilities/database/database_connection.py", line 92, in run
    raise_from(SpinnmanIOException(str(e)), e)
  File "/home/dyck/.local/lib/python2.7/site-packages/six.py", line 737, in raise_from
    raise value
SpinnmanIOException: IO Error: no such table: configuration_parameters

which results in a simulation loop where the spike connection isn’t established:

[spinn_front_end_common.interface.abstract_spinnaker_base][INFO] 2018-12-18 16:32:01,153: Run 1 of 1
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,230: Spike could not be injected as spike connection not started, yet
clearing IOBUF from the machine
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:01,255: Time 0:00:00.001711 taken by ChipIOBufClearer
Reloading data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:01,256: Time 0:00:00.001113 taken by DSGRegionReloader
Updating run time
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:01,268: Time 0:00:00.012026 taken by ChipRuntimeUpdater
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:01,269: Time 0:00:00.000171 taken by DatabaseInterface
UDPConnection init 0
127.0.0.1
UDPConnection init 1
44848
UDPConnection init 0
127.0.0.1
UDPConnection init 1
52862
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:01,270: Time 0:00:00.001233 taken by NotificationProtocol
[spinn_front_end_common.interface.interface_functions.application_runner][INFO] 2018-12-18 16:32:01,271: *** Running simulation... *** 
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,278: Spike could not be injected as spike connection not started, yet
Loading buffers (0 bytes)
|0%                          50%                         100%|
 ============================================================
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,330: Spike could not be injected as spike connection not started, yet
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-18 16:32:01,348: ** Sending start / resume message to external sources to state the simulation has started or resumed. **
[spinn_front_end_common.interface.interface_functions.application_runner][INFO] 2018-12-18 16:32:01,348: Application started; waiting 1.1s for it to stop
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,386: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,439: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,493: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,546: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,599: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,651: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,703: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,756: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,808: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,862: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,915: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:01,967: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:02,020: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:02,074: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:02,129: Spike could not be injected as spike connection not started, yet
[hbp_nrp_cle.brainsim.pynn_spiNNaker.devices.__SpikeInjector][WARNING] 2018-12-18 16:32:02,193: Spike could not be injected as spike connection not started, yet
[spinn_front_end_common.utilities.notification_protocol.notification_protocol][INFO] 2018-12-18 16:32:02,471: ** Sending pause / stop message to external sources to state the simulation has been paused or stopped. **
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,471: Time 0:00:01.200450 taken by ApplicationRunner
Extracting buffers from the last run
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,479: Time 0:00:00.007455 taken by BufferExtractor
Getting provenance data from machine graph
|0%                          50%                         100%|
 ============================================================
Getting provenance data from application graph
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,480: Time 0:00:00.001310 taken by GraphProvenanceGatherer
Getting provenance data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,488: Time 0:00:00.007127 taken by PlacementsProvenanceGatherer
Getting Router Provenance
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,576: Time 0:00:00.087533 taken by RouterProvenanceGatherer
Getting profile data
|0%                          50%                         100%|
 ============================================================
[pacman.executor.pacman_algorithm_executor][INFO] 2018-12-18 16:32:02,580: Time 0:00:00.003808 taken by ProfileDataGatherer
_write_provenance
/tmp/nrp-simulation-dir/reports/2018-12-18-16-31-14-420133/run_1/provenance_data

[/EDIT]

My question is now: Is there some obvious problem with the SpiNNaker board/connection/setup that causes the very slow simulation time and might be the reason why it is so far from real time?

Any help is appreciated,
Thank you very much!

Best,
Michael


#2

@cyb3: This discussion board is for the Spinnaker continuous deployment tool (https//spinnaker.io). It looks like this question is about a different SpiNNaker (which I actually only learned about today after reading this question). I don’t think anyone here will be able to help with this question. Thanks! Eric


#3

Hey,

thanks for your answer though.
I’m sorry about that. You can just delete this post then.

Best,
cyb3