[SMPI] Something wrong about job management

mpoquet commented 7 years ago

Abstract

Something is wrong about the management of SMPI jobs in Batsim. When long jobs are executed, Batsim states they are finished way before they actually are.

How to reproduce ?

Versions

Batsim version : b10cb66371bc8dbfd (master branch) SimGrid version : oar-team/simgrid-batsim, batsim-compatible, 42a5c2c5fa27026391c

Step 1 (necessary to generate some files)

cd ${BATSIM_BASE_DIR}
./test/run_tests.sh

Execute Batsim command (in one terminal)

cd ${BATSIM_BASE_DIR}
./test/out/smpi/results/fillerSched_compute/batsim_command.sh

Execute sched command (in another terminal)

cd ${BATSIM_BASE_DIR}
./test/out/smpi/results/fillerSched_compute/sched_command.sh

Expected results

The makespan should be 15.00039 whereas the simulation finishes at 20621958276.156872 !

Batsim output

[0.000000] [workload/INFO] Loading JSON workload 'workload_profiles/test_smpi_compute_only.json'...
[0.000000] [profiles/INFO] baseDIR = 'workload_profiles'
[0.000000] [profiles/INFO] trace = 'smpi/compute_only/traces.txt'
[0.000000] [profiles/INFO] tracePath = 'workload_profiles/smpi/compute_only/traces.txt'
[0.000000] [workload/INFO] JSON workload parsed sucessfully.
[0.000000] [workload/INFO] Checking workload validity...
[0.000000] [workload/INFO] Workload seems to be valid.
[0.000000] [batsim/INFO] The number of machines will be limited to 4
[0.000000] [batsim/INFO] Checking whether SMPI is used or not...
[0.000000] [batsim/INFO] SMPI will be used.
[0.000000] [workload/INFO] Registering SMPI applications...
[0.000000] [workload/INFO] Registering app. instance='1', nb_process=2
[0.000000] [workload/INFO] SMPI applications have been registered
[0.000000] [smpi_kernel/INFO] You did not set the power of the host running the simulation.  The timings will certainly not be accurate.  Use the option "--cfg=smpi/host-speed:<flops>" to set its value.Check http://simgrid.org/simgrid/latest/doc/options.html#options_smpi_bench for more information.
[0.000000] [batsim/INFO] Creating the machines...
[0.000000] [batsim/INFO] Machines created successfully. There are 4 computing machines.
[0.000000] [network/INFO] Creating UDS socket on 'test/out/smpi/results/fillerSched_compute/socket'
[0.000000] [network/INFO] Waiting for an incoming connection...
[0.000000] [network/INFO] Connected!
[0.000000] [batsim/INFO] Creating jobs_submitter process...
[0.000000] [batsim/INFO] The jobs_submitter process has been created.
[0.000000] [batsim/INFO] Creating the uds_server process...
[0.000000] [batsim/INFO] The uds_server process has been created.
[master_host:jobs_submitter:(1) 0.000000] [ipp/INFO] message from 'jobs_submitter' to 'server' of type 'SUBMITTER_HELLO' with data (nil)
[master_host:server:(2) 0.000195] [server/INFO] Server received a message of type SUBMITTER_HELLO:
[master_host:server:(2) 0.000195] [server/INFO] New submitter said hello. Number of polite submitters: 1
[master_host:jobs_submitter:(1) 10.000000] [ipp/INFO] message from 'jobs_submitter' to 'server' of type 'JOB_SUBMITTED' with data 0x1ed8300
[master_host:server:(2) 10.000195] [server/INFO] Server received a message of type JOB_SUBMITTED:
[master_host:server:(2) 10.000195] [server/INFO] Job 1 SUBMITTED. 1 jobs submitted so far
[master_host:jobs_submitter:(1) 10.000195] [ipp/INFO] message from 'jobs_submitter' to 'server' of type 'SUBMITTER_BYE' with data (nil)
[master_host:Scheduler REQ-REP:(3) 10.000195] [network/INFO] Sending '1:10.000195|10.000195:S:1'
[master_host:Scheduler REQ-REP:(3) 10.000195] [network/INFO] Received '0:10.000195|15.000195:J:1=0,1'
[master_host:server:(2) 10.000390] [server/INFO] Server received a message of type SUBMITTER_BYE:
[master_host:server:(2) 10.000390] [server/INFO] A submitted said goodbye. Number of finished submitters: 1
[master_host:Scheduler REQ-REP:(3) 15.000195] [ipp/INFO] message from 'Scheduler REQ-REP' to 'server' of type 'SCHED_ALLOCATION' with data 0x1e57330
[master_host:server:(2) 15.000390] [server/INFO] Server received a message of type SCHED_ALLOCATION:
[master_host:Scheduler REQ-REP:(3) 15.000390] [ipp/INFO] message from 'Scheduler REQ-REP' to 'server' of type 'SCHED_READY' with data (nil)
[Bourassa:job1:(4) 15.000390] [jobs_execution/INFO] Job 1 finished in time
[Bourassa:job1:(4) 15.000390] [ipp/INFO] message from 'job1' to 'server' of type 'JOB_COMPLETED' with data 0x1f7f620
[master_host:server:(2) 15.000585] [server/INFO] Server received a message of type SCHED_READY:
[master_host:server:(2) 15.026025] [server/INFO] Server received a message of type JOB_COMPLETED:
[master_host:server:(2) 15.026025] [server/INFO] Job 1 COMPLETED. 1 jobs completed so far
[master_host:Scheduler REQ-REP:(7) 15.026025] [network/INFO] Sending '1:15.026025|15.026025:C:1'
[master_host:Scheduler REQ-REP:(7) 15.026025] [network/INFO] Received '0:15.026025|20.026025:N'
[master_host:Scheduler REQ-REP:(7) 20.026025] [ipp/INFO] message from 'Scheduler REQ-REP' to 'server' of type 'SCHED_NOP' with data (nil)
[master_host:server:(2) 20.026220] [server/INFO] Server received a message of type SCHED_NOP:
[master_host:server:(2) 20.026220] [server/INFO] Nothing to do received.
[master_host:Scheduler REQ-REP:(7) 20.026220] [ipp/INFO] message from 'Scheduler REQ-REP' to 'server' of type 'SCHED_READY' with data (nil)
[master_host:server:(2) 20.026415] [server/INFO] Server received a message of type SCHED_READY:
[master_host:server:(2) 20.026415] [server/INFO] All jobs completed!
[Bourassa:1_0:(5) 20621958276.156872] [smpi_replay/INFO] Simulation time 20621958261.156483
[20621958276.156872] [export/INFO] PajeTracer finalized
[20621958276.156872] [export/INFO] Makespan=15.000390, scheduling_time=0.000425

Scheduler output

Starting simulation...
Workload: workload_profiles/test_smpi_compute_only.json
Scheduler: fillerSched
Options: {}
[BATSIM]: connecting to 'test/out/smpi/results/fillerSched_compute/socket'
('openJobs = ', set([<Job 1; sub:10 res:2 reqtime:100 prof:1>]))
('available = ', SortedSet([0, 1, 2, 3], key=None, load=1000))
('previous = ', {})
('openJobs = ', set([]))
('available = ', SortedSet([2, 3], key=None, load=1000))
('previous = ', {1: [0, 1]})

('openJobs = ', set([]))
('available = ', SortedSet([0, 1, 2, 3], key=None, load=1000))
('previous = ', {})
('openJobs = ', set([]))
('available = ', SortedSet([0, 1, 2, 3], key=None, load=1000))
('previous = ', {})

[BATSIM]: connection is closed by batsim core
Simulation ran for: 0:00:00.003682
Job received: 1 , scheduled: 1 , in the workload: 1

mpoquet commented 7 years ago

smpi_replay_run seems to be blocking.

We should just synchronise two batsim processes: smpi_replay_process and its calling process (called through execute_profile).

augu5te commented 7 years ago

Trouble comes from calls of MSG_process_create_with_arguments which which call smpi_replay_process. A solution is to add a semaphore between MSG_process execute_profile and one of MSG_process_process_create_with_arguments. Added in https://github.com/oar-team/batsim/commit/4e8b3cef41619776225513d9a5d86a7f2f5fa4d6

mpoquet commented 7 years ago

Simulation time inconsistency fixed by 4e8b3ce.

Closing this issue, but SMPI still does NOT work in Batsim (see issue #13).

oar-team / batsim