Getting semaphore error when using parallel processes

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

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

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

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 #2 ***
UVVM: 5367 ns TB seq.
UVVM: check_value() => Failed. int Was 100. Expected 50
UVVM: Num ones read for PWM input 1 is 100. Expected num ones is 50
UVVM: =========================================================================================================================================================================
UVVM:
UVVM:
UVVM: ID_UVVM_SEND_CMD 5367.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"0018"): ‘Read from Result reg 2’. [152]
UVVM: ID_CMD_INTERPRETER_WAIT 5367.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_CMD_INTERPRETER 5367.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"0018"). Command received [152]
UVVM: ID_UVVM_CMD_ACK 5367.0 ns TB seq.(uvvm) ACK received. [152]
UVVM: ID_CMD_EXECUTOR 5367.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
UVVM: ID_AWAIT_COMPLETION 5367.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns): ‘Wait for read to finish’. [153]
UVVM: ID_AWAIT_COMPLETION_WAIT 5367.0 ns TB seq.(uvvm) …await_completion(AXILITE_VVC,1, 100 ns) - Pending completion. ‘Wait for read to finish’ [153]
UVVM: ID_CMD_INTERPRETER_WAIT 5367.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_CHANNEL_EXECUTOR 5367.0 ns AXILITE_VVC_AR,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
UVVM: ID_CHANNEL_EXECUTOR 5367.0 ns AXILITE_VVC_R,1 axilite_read(AXILITE_VVC,1, x"0018") - Will be executed [152]
UVVM: ID_CMD_EXECUTOR_WAIT 5367.0 ns AXILITE_VVC,1 …Executor: Waiting for command
UVVM: ID_CHANNEL_BFM 5407.0 ns AXILITE_VVC_AR,1 read_address_channel_write(x"18") completed. ‘Read from Result reg 2’ [152]
UVVM: ID_CHANNEL_EXECUTOR_WAIT 5407.0 ns AXILITE_VVC_AR,1 Executor: Waiting for command
UVVM: ID_BFM 5417.0 ns AXILITE_VVC_R,1 read_data_channel_receive()=> x"64". ‘Read from Result reg 2’ [152]
UVVM: ID_AWAIT_COMPLETION_END 5417.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns)=> AXILITE_VVC,1 finished. ‘Wait for read to finish’
UVVM: [153]
UVVM: ID_UVVM_SEND_CMD 5417.0 ns TB seq.(uvvm) ->fetch_result(AXILITE_VVC,1, 152): ‘Fetching result from read operation’. [154]
UVVM: ID_CHANNEL_EXECUTOR_WAIT 5417.0 ns AXILITE_VVC_R,1 Executor: Waiting for command
UVVM: ID_CMD_INTERPRETER 5417.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 152). Command received [154]
UVVM: ID_IMMEDIATE_CMD 5417.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 152) Requested result is found. Fetching result from read operation
UVVM: [154]
UVVM: ID_UVVM_CMD_ACK 5417.0 ns TB seq.(uvvm) ACK received. [154]
UVVM: ID_UVVM_CMD_RESULT 5417.0 ns TB seq.(uvvm) fetch_result(AXILITE_VVC,1, 152): Legal=>true, Result=> [154]
UVVM:
UVVM: =========================================================================================================================================================================
UVVM: *** ERROR #3 ***
UVVM: 5417 ns TB seq.
UVVM: check_value() => Failed. int Was 100. Expected 75
UVVM: Num ones read for PWM input 2 is 100. Expected num ones is 75
UVVM: =========================================================================================================================================================================
UVVM:
UVVM:
UVVM: ID_UVVM_SEND_CMD 5417.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"001C"): ‘Read from Result reg 3’. [155]
UVVM: ID_CMD_INTERPRETER_WAIT 5417.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_CMD_INTERPRETER 5417.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"001C"). Command received [155]
UVVM: ID_UVVM_CMD_ACK 5417.0 ns TB seq.(uvvm) ACK received. [155]
UVVM: ID_CMD_EXECUTOR 5417.0 ns AXILITE_VVC,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
UVVM: ID_AWAIT_COMPLETION 5417.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns): ‘Wait for read to finish’. [156]
UVVM: ID_AWAIT_COMPLETION_WAIT 5417.0 ns TB seq.(uvvm) …await_completion(AXILITE_VVC,1, 100 ns) - Pending completion. ‘Wait for read to finish’ [156]
UVVM: ID_CMD_INTERPRETER_WAIT 5417.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_CHANNEL_EXECUTOR 5417.0 ns AXILITE_VVC_AR,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
UVVM: ID_CHANNEL_EXECUTOR 5417.0 ns AXILITE_VVC_R,1 axilite_read(AXILITE_VVC,1, x"001C") - Will be executed [155]
UVVM: ID_CMD_EXECUTOR_WAIT 5417.0 ns AXILITE_VVC,1 …Executor: Waiting for command
UVVM: ID_CHANNEL_BFM 5457.0 ns AXILITE_VVC_AR,1 read_address_channel_write(x"1C") completed. ‘Read from Result reg 3’ [155]
UVVM: ID_CHANNEL_EXECUTOR_WAIT 5457.0 ns AXILITE_VVC_AR,1 Executor: Waiting for command
UVVM: ID_BFM 5467.0 ns AXILITE_VVC_R,1 read_data_channel_receive()=> x"64". ‘Read from Result reg 3’ [155]
UVVM: ID_AWAIT_COMPLETION_END 5467.0 ns TB seq.(uvvm) await_completion(AXILITE_VVC,1, 100 ns)=> AXILITE_VVC,1 finished. ‘Wait for read to finish’
UVVM: [156]
UVVM: ID_UVVM_SEND_CMD 5467.0 ns TB seq.(uvvm) ->fetch_result(AXILITE_VVC,1, 155): ‘Fetching result from read operation’. [157]
UVVM: ID_CHANNEL_EXECUTOR_WAIT 5467.0 ns AXILITE_VVC_R,1 Executor: Waiting for command
UVVM: ID_CMD_INTERPRETER 5467.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 155). Command received [157]
UVVM: ID_IMMEDIATE_CMD 5467.0 ns AXILITE_VVC,1 fetch_result(AXILITE_VVC,1, 155) Requested result is found. Fetching result from read operation
UVVM: [157]
UVVM: ID_UVVM_CMD_ACK 5467.0 ns TB seq.(uvvm) ACK received. [157]
UVVM: ID_UVVM_CMD_RESULT 5467.0 ns TB seq.(uvvm) fetch_result(AXILITE_VVC,1, 155): Legal=>true, Result=> [157]
UVVM: ID_POS_ACK 5467.0 ns TB seq. check_value() => OK, for int 100. ‘Num ones read for PWM input 3 is 100. Expected num ones is
UVVM: 100’
UVVM: ID_CMD_INTERPRETER_WAIT 5467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_UVVM_SEND_CMD 7467.0 ns TB seq.(uvvm) ->axilite_check(AXILITE_VVC,1, x"04", x"00000001"): ‘Expect bit 0 in STAT register to be ‘1’.
UVVM: Measurements should have been updated’. [158]
UVVM: ID_CMD_INTERPRETER 7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001"). Command received [158]
UVVM: ID_UVVM_CMD_ACK 7467.0 ns TB seq.(uvvm) ACK received. [158]
UVVM: ID_CMD_EXECUTOR 7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
UVVM: ID_BLOCKING 7467.0 ns TB seq. check_parallel: Unblocking flag. ‘start parallel checks done’
UVVM: ID_CMD_INTERPRETER_WAIT 7467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_BLOCKING 7467.0 ns TB seq. check_parallel: Has been unblocked.
UVVM: ID_UVVM_SEND_CMD 7467.0 ns TB seq.(uvvm) ->axilite_check(AXILITE_VVC,1, x"08", x"00000000"): ‘Expect all zeroes in CTRL reg’. [159]
UVVM: ID_CMD_INTERPRETER 7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"08", x"00000000"). Command received [159]
UVVM: ID_UVVM_SEND_CMD 7467.0 ns TB seq.(uvvm) ->axilite_read(AXILITE_VVC,1, x"0010"): ‘Read from Result reg 0’. [160]
UVVM: ID_UVVM_CMD_ACK 7467.0 ns TB seq.(uvvm) ACK received. [159]
UVVM: ID_CHANNEL_EXECUTOR 7467.0 ns AXILITE_VVC_AR,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
UVVM: ID_CHANNEL_EXECUTOR 7467.0 ns AXILITE_VVC_R,1 axilite_check(AXILITE_VVC,1, x"04", x"00000001") - Will be executed [158]
UVVM: ID_CMD_INTERPRETER_WAIT 7467.0 ns AXILITE_VVC,1 …Interpreter: Waiting for command
UVVM: ID_CMD_EXECUTOR 7467.0 ns AXILITE_VVC,1 axilite_check(AXILITE_VVC,1, x"08", x"00000000") - Will be executed [159]
UVVM: ID_CMD_EXECUTOR_WAIT 7467.0 ns AXILITE_VVC,1 …Executor: Waiting for command
UVVM:
UVVM: =========================================================================================================================================================================
UVVM: *** TB_ERROR #1 ***
UVVM: 7467 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: =========================================================================================================================================================================
UVVM:
UVVM:

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

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

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

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

Yes sure I can do that.

Hannu

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

Br,
Marius

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