Getting semaphore error when using parallel processes

Hannu · March 25, 2021, 1:32pm

Hi

We are running tests in multiple processes. DUT initialization is done in one process and then the tests are run in parallel processes. Register writes/reads are done through VVC methods in the parallel processes. Processes are not synchronized so from time to time some VVCs are tried to be accessed somehow in same time.
For example, when some reading and fetch_result are done, something happens at the same time and we are getting semaphore error:

UVVM:=====================================================================
UVVM: *** TB_ERROR #1 ***
UVVM: 707070 ns TB seq.(uvvm)
UVVM: Failed to acquire semaphore when sending command to VVC
UVVM:
UVVM: Simulator has been paused as requested after 1 TB_ERROR
UVVM: *** To find the root cause of this alert, step out the HDL calling stack in your simulator. ***
UVVM: *** For example, step out until you reach the call from the test sequencer.
UVVM:=====================================================================

Are these methods supposed to be usable this way?
Are we misusing something?
Or should it be taken care in test sequency that parallel accesses do not happen?

Regards,
Hannu

EspenTa · March 29, 2021, 2:59pm

Hi Hannu,

I assume you are using the old await_completion?
Could you please list the commands you are using and specify which is called from which process?
Are you using Bitvis VVCs, og have you made your own?
(If you are using only Bitvis VVCs you could try to switch to the newer await_completion. If so, check out the current documentation.

Regards
Espen

Hannu · April 9, 2021, 1:39pm

Hi,

Example sequency is described below. Main process is reading and then the parallel process starts when it is unblocked.
Version used is v2 2020.12.08. And here Bitvis axilite vvc is used.
What do you mean with newer await_completion? What should be used from there?

initializatons and start of test… then:

unblock_flag("check_parallel", "start parallel checks ", global_trigger, C_SCOPE);

for i in 0 to PWM_INPUT_CNT-1 loop
  axilite_read(AXILITE_VVCT, 1, M0_RESULT_ADDR + x"04"*i, "Read from Result reg " & integer'image(i));
  v_cmd_idx := get_last_received_cmd_idx(AXILITE_VVCT, 1);
  await_completion(AXILITE_VVCT, 1, 100 ns, "Wait for read to finish");
  fetch_result(AXILITE_VVCT,1, v_cmd_idx, read_data, "Fetching result from read operation"); 
  data_int := to_integer(unsigned(read_data(31 downto 0)));
  
  check_value(data_int, 0, ERROR, "Num ones read for PWM input " & integer'image(i) & " is " & integer'image(data_int) & ". Expected num ones is 0");
end loop;    

-- Finish the simulation
std.env.stop;
wait;                               -- to stop completely

end process p_main;

Parallel process:

parallel_check_process : process is

begin

-- Wait for UVVM to finish initialization
await_uvvm_initialization(VOID);  
await_unblock_flag("check_parallel", 100 ms, "start parallel checks ", KEEP_UNBLOCKED, failure);

loop    

 axilite_check(AXILITE_VVCT, 1, CTRL_ADDR, x"00000000", "Expect all zeroes in CTRL reg", error);
 await_completion(AXILITE_VVCT, 1, C_TIMEOUT, "Waiting for register check to finish");  

end loop; 
    
wait;

end process parallel_check_process;

Regards,
Hannu

Hannu · April 16, 2021, 10:44am

Hi

Logs enabled and some last printouts from the test below. I wasn’t able to attach the whole log file.
Hopefully all the interesting stuff is visible at the end. (Dont care about the check_value errors)

Regards
Hannu

======================== UVVM: *** ERROR UVVM: 5367 ns TB seq.
UVVM: UVVM: UVVM: ================== UVVM:
UVVM:
UVVM: ID_UVVM_SEND_CMD UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_CMD_INTERPRETER UVVM: ID_UVVM_CMD_ACK UVVM: ID_CMD_EXECUTOR UVVM: ID_AWAIT_COMPLETION UVVM: ID_AWAIT_COMPLETION_WAIT UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CMD_EXECUTOR_WAIT UVVM: ID_CHANNEL_BFM UVVM: ID_CHANNEL_EXECUTOR_WAIT UVVM: ID_BFM UVVM: ID_AWAIT_COMPLETION_END UVVM: UVVM: ID_UVVM_SEND_CMD UVVM: ID_CHANNEL_EXECUTOR_WAIT UVVM: ID_CMD_INTERPRETER UVVM: ID_IMMEDIATE_CMD UVVM: UVVM: ID_UVVM_CMD_ACK UVVM: ID_UVVM_CMD_RESULT UVVM:
UVVM: ================== UVVM: *** ERROR UVVM: 5417 ns TB seq.
UVVM: UVVM: UVVM: ================== UVVM:
UVVM:
UVVM: ID_UVVM_SEND_CMD UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_CMD_INTERPRETER UVVM: ID_UVVM_CMD_ACK UVVM: ID_CMD_EXECUTOR UVVM: ID_AWAIT_COMPLETION UVVM: ID_AWAIT_COMPLETION_WAIT UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CMD_EXECUTOR_WAIT UVVM: ID_CHANNEL_BFM UVVM: ID_CHANNEL_EXECUTOR_WAIT UVVM: ID_BFM UVVM: ID_AWAIT_COMPLETION_END UVVM: UVVM: ID_UVVM_SEND_CMD UVVM: ID_CHANNEL_EXECUTOR_WAIT UVVM: ID_CMD_INTERPRETER UVVM: ID_IMMEDIATE_CMD UVVM: UVVM: ID_UVVM_CMD_ACK UVVM: ID_UVVM_CMD_RESULT UVVM: ID_POS_ACK UVVM: UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_UVVM_SEND_CMD UVVM: UVVM: ID_CMD_INTERPRETER UVVM: ID_UVVM_CMD_ACK UVVM: ID_CMD_EXECUTOR UVVM: ID_BLOCKING UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_BLOCKING UVVM: ID_UVVM_SEND_CMD UVVM: ID_CMD_INTERPRETER UVVM: ID_UVVM_SEND_CMD UVVM: ID_UVVM_CMD_ACK UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CHANNEL_EXECUTOR UVVM: ID_CMD_INTERPRETER_WAIT UVVM: ID_CMD_EXECUTOR UVVM: ID_CMD_EXECUTOR_WAIT UVVM:
UVVM: ================== UVVM: *** TB_ERROR UVVM: 7467 ns UVVM: UVVM:
UVVM: Simulator UVVM: *** To find UVVM: *** For example, UVVM: ================== UVVM:
UVVM: =================================================================================================================================================
#2 ***
check_value() => Failed. int Was 100. Expected 50
Num ones read for PWM input 1 is 100. Expected num ones is 50
=======================================================================================================================================================
5367.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"0018"): ‘Read from Result reg 2’. [152]
5367.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
5367.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"0018"). Command received [152]
5367.0 ns TB seq.(uvvm) ACK received. [152]
5367.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
5367.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns): ‘Wait for read to finish’. [153]
5367.0 ns TB seq.(uvvm) …await_completion(AXILITE_VVC,1, 100 ns) - Pending completion. ‘Wait for read to finish’ [153]
5367.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
5367.0 ns AXILITE_VVC_AR,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
5367.0 ns AXILITE_VVC_R,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
5367.0 ns AXILITE_VVC,1 …Executor: Waiting for command
5407.0 ns AXILITE_VVC_AR,1 read_address_channel_write(x"18") completed. ‘Read from Result reg 2’ [152]
5407.0 ns AXILITE_VVC_AR,1 Executor: Waiting for command
5417.0 ns AXILITE_VVC_R,1 read_data_channel_receive()=> x"64". ‘Read from Result reg 2’ [152]
5417.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns)=> AXILITE_VVC,1 finished. ‘Wait for read to finish’
[153]
5417.0 ns TB seq.(uvvm) ->fetch_result(AXILITE_VVC,1, 152): ‘Fetching result from read operation’. [154]
5417.0 ns AXILITE_VVC_R,1 Executor: Waiting for command
5417.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 152). Command received [154]
5417.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 152) Requested result is found. Fetching result from read operation
[154]
5417.0 ns TB seq.(uvvm) ACK received. [154]
5417.0 ns TB seq.(uvvm) fetch_result(AXILITE_VVC,1, 152): Legal=>true, Result=> [154]
=======================================================================================================================================================
#3 ***
check_value() => Failed. int Was 100. Expected 75
Num ones read for PWM input 2 is 100. Expected num ones is 75
=======================================================================================================================================================
5417.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"001C"): ‘Read from Result reg 3’. [155]
5417.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
5417.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"001C"). Command received [155]
5417.0 ns TB seq.(uvvm) ACK received. [155]
5417.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
5417.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns): ‘Wait for read to finish’. [156]
5417.0 ns TB seq.(uvvm) …await_completion(AXILITE_VVC,1, 100 ns) - Pending completion. ‘Wait for read to finish’ [156]
5417.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
5417.0 ns AXILITE_VVC_AR,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
5417.0 ns AXILITE_VVC_R,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
5417.0 ns AXILITE_VVC,1 …Executor: Waiting for command
5457.0 ns AXILITE_VVC_AR,1 read_address_channel_write(x"1C") completed. ‘Read from Result reg 3’ [155]
5457.0 ns AXILITE_VVC_AR,1 Executor: Waiting for command
5467.0 ns AXILITE_VVC_R,1 read_data_channel_receive()=> x"64". ‘Read from Result reg 3’ [155]
5467.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns)=> AXILITE_VVC,1 finished. ‘Wait for read to finish’
[156]
5467.0 ns TB seq.(uvvm) ->fetch_result(AXILITE_VVC,1, 155): ‘Fetching result from read operation’. [157]
5467.0 ns AXILITE_VVC_R,1 Executor: Waiting for command
5467.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 155). Command received [157]
5467.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 155) Requested result is found. Fetching result from read operation
[157]
5467.0 ns TB seq.(uvvm) ACK received. [157]
5467.0 ns TB seq.(uvvm) fetch_result(AXILITE_VVC,1, 155): Legal=>true, Result=> [157]
5467.0 ns TB seq. check_value() => OK, for int 100. ‘Num ones read for PWM input 3 is 100. Expected num ones is
100’
5467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
7467.0 ns TB seq.(uvvm) ->axilite_check(AXILITE_VVC,1, x"04", x"00000001"): ‘Expect bit 0 in STAT register to be ‘1’.
Measurements should have been updated’. [158]
7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001"). Command received [158]
7467.0 ns TB seq.(uvvm) ACK received. [158]
7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
7467.0 ns TB seq. check_parallel: Unblocking flag. ‘start parallel checks done’
7467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
7467.0 ns TB seq. check_parallel: Has been unblocked.
7467.0 ns TB seq.(uvvm) ->axilite_check(AXILITE_VVC,1, x"08", x"00000000"): ‘Expect all zeroes in CTRL reg’. [159]
7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"08", x"00000000"). Command received [159]
7467.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"0010"): ‘Read from Result reg 0’. [160]
7467.0 ns TB seq.(uvvm) ACK received. [159]
7467.0 ns AXILITE_VVC_AR,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
7467.0 ns AXILITE_VVC_R,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
7467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"08", x"00000000") - Will be executed [159]
7467.0 ns AXILITE_VVC,1 …Executor: Waiting for command
=======================================================================================================================================================
#1 ***
TB seq.(uvvm)
Failed to acquire semaphore when sending command to VVC
has been paused as requested after 1 TB_ERROR
the root cause of this alert, step out the HDL calling stack in your simulator. ***
step out until you reach the call from the test sequencer. ***
=======================================================================================================================================================

EspenTa · April 19, 2021, 6:32pm

Hi,
I think you have included a sufficient part of the log, and at least from my first understanding it seems that the testbench code is OK.
Are all the UVVM commands at time 7467 ns from the same process (it seems so from the log, but there is no way to tell if in fact some of these commands come from to different processes)? And independent of that I think this should still have worked.
I suspect that you may have found a failing corner case inside the AXILITE VVC, but I am not the expert on this module, so I will check with the AXILITE VVC author.
In the meantime - did you check your TB using the full AXI VVC? That might behave slightly differently.

– Espen

Hannu · April 20, 2021, 6:46pm

Hi
Commands are coming from two different processes.
Similar behavior is seen at least with some of our own VVCs also so not only with AXILITE VVC.

Regards
Hannu

EspenTa · April 27, 2021, 4:47pm

Hi,
We have managed to reproduce this on our side as well, and it is definitely a bug. We will try to find a good solution, but unfortunately I have been extremely busy just now, and will be until Tuesday next week. We will do some investigations during this week, but will most probably not have time to dive properly into this before the middle of next week.
– Espen

EspenTa · May 4, 2021, 9:03am

Hi,
We have found the source of this problem and we think we have good solution. We will now implement this and run our regression suite extended with a new case for this issue. It would be great if you could try this out before we release it - to make sure your TB works properly.after the update and that we have solved everything.
Is that OK?
– Espen

Hannu · May 4, 2021, 9:24am

Yes sure I can do that.

Hannu

Marius · May 25, 2021, 1:57pm

Hi Hannu,
I’ve implemented a fix and running tests now. Hopefully all is good and I can publish a release soon.

Br,
Marius

Marius · May 26, 2021, 1:24pm

Hi Hannu,
My implementations passed the tests so I’ve added the fix and published a new release of UVVM today - version v2021.05.26.

Best regards,
Marius

Topic		Replies	Views
" Failed to acquire semaphore when sending command to VVC" General questions	4	532	July 8, 2022
Issue with await_value Bitvis VIP I2C uvvm	7	741	August 31, 2021
Await_value utils functionality issue Utility Library uvvm , question	7	822	July 9, 2021
Time out for uvvm cmd Bitvis VIP I2C uvvm	7	549	December 19, 2021
Test bench hangs up on wait statement General questions question	5	582	February 2, 2021

Getting semaphore error when using parallel processes

Related topics