cocotb slow down with long testbenches

[scolabirra]

I noticed that my cocotb testbenches are starting to slow down when they are long. As example, I use the "parametrize" command in cocotb that allows to perform the same test by changing the parameters. The test itself it's always the same amount of clock cycles, but as long as it tests new parameters the duration of the test is longer and longer. I tried to understand what's going on and I found a lot of active handles in the warning with the --vhpi-debug option. I report below what I get. If the test is repeated or it's longer, the number of active handles increases, and maybe the reason of the slow down is due to it. I tried an old r1.11 version and I didn't see any slow-down nor any warning at the end of the test.

** Warning: VHPI program exited with 36 active handles
            0x100000000:{vhpiCallbackK Reason=vhpiCbStartOfSimulation State=vhpiMature} with 1 references
            0x100000001:{vhpiCallbackK Reason=vhpiCbEndOfSimulation State=vhpiMature} with 1 references
            0x100000003:{vhpiIteratorK pos=0/0} with 1 references
            0x100000004:{vhpiArchBodyK} with 1 references
            0x100000005:{vhpiEntityDeclK} with 1 references
            0x100000007:{vhpiEnumTypeDeclK Name=STD_ULOGIC} with 9 references
            0x10000000b:{vhpiArrayTypeDeclK Name=STD_ULOGIC_VECTOR} with 1 references
            0x10000000d:{vhpiIntRangeK IsNull=0 IsUp=0 IsUnconstrained=0} with 1 references
            0x20000000e:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000010:{vhpiArrayTypeDeclK Name=STD_ULOGIC_VECTOR} with 1 references
            0x100000012:{vhpiIntRangeK IsNull=0 IsUp=0 IsUnconstrained=0} with 1 references
            0x100000013:{vhpiArrayTypeDeclK Name=STD_ULOGIC_VECTOR} with 1 references
            0x200000014:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000015:{vhpiIntRangeK IsNull=0 IsUp=0 IsUnconstrained=0} with 1 references
            0x100000016:{vhpiCallbackK Reason=vhpiCbRepLastKnownDeltaCycle State=vhpiEnable} with 1 references
            0x100000017:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000018:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000019:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001a:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001b:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001c:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001d:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001e:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000001f:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000020:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x300000021:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000022:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000023:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000026:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000027:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000028:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x100000029:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000002a:{vhpiArrayTypeDeclK Name=STD_ULOGIC_VECTOR} with 1 references
            0x20000002b:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references
            0x10000002c:{vhpiIntRangeK IsNull=0 IsUp=0 IsUnconstrained=0} with 1 references
            0x10000002d:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable} with 2 references

[nickg]

Is it possible to reproduce this with the examples in the cocotb repository?

If the test is repeated or it's longer, the number of active handles increases, and maybe the reason of the slow down is due to it.

Can you see which type of handles increase with the number of iterations? E.g. is it vhpiCallbackK?

[scolabirra]

Yes, it's mostly vhpiCallbackK. Anyway, I've been able to isolate part of the problem. please find below a simple test that slows down and generate a log of vhpiCallbackK.

library ieee;
use ieee.std_logic_1164.all;
use ieee.numeric_std.all;

entity test is
  port (
    run  : in  std_ulogic
  );
end entity test;

architecture rtl of test is
  signal ck : std_ulogic;
  constant f_ck : real := 20.0e6;
begin

  p_ck_rst: process
  begin
    ck <= '0';
    wait until run'event and run = '1';
    wait for 1 us;
    while run = '1' or ck = '1' loop
      ck <= not ck;
      wait for (0.5/f_ck) * sec;
    end loop;
  end process;

end rtl;

import cocotb


@cocotb.test()
@cocotb.parametrize(a = list(range(256)), b = list(range(256)))
async def tst_add(dut, a, b):
    tc = cocotb.triggers.RisingEdge(dut.ck)
    dut.run.value = 0
    await cocotb.triggers.Timer(1, "us")
    dut.run.value = 1
    for k in range(5):
        await tc

[nickg]

I think the problem here is that cocotb never releases callbacks with vhpi_remove_cb, it only disables them with vhpi_disable_cb. It's always for the CK signal so I guess it's caused by the RisingEdge object getting recreated each time the test function is executed.

VHPI: vhpi_register_cb cb_datap_p={reason=vhpiCbValueChange obj=0x100000006:{vhpiSigDeclK Name=CK} cb_rtn=0x7f95163331a0 user_data=0x561053c16d30} flags=1
VHPI: vhpi_disable_cb cb_obj=0x200000140:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_disable_cb cb_obj=0x200000141:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_register_cb cb_datap_p={reason=vhpiCbValueChange obj=0x100000006:{vhpiSigDeclK Name=CK} cb_rtn=0x7f95163331a0 user_data=0x561053c16e00} flags=1
VHPI: vhpi_disable_cb cb_obj=0x200000141:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_disable_cb cb_obj=0x100000142:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_register_cb cb_datap_p={reason=vhpiCbValueChange obj=0x100000006:{vhpiSigDeclK Name=CK} cb_rtn=0x7f95163331a0 user_data=0x561053c16f10} flags=1
VHPI: vhpi_disable_cb cb_obj=0x100000142:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_disable_cb cb_obj=0x100000143:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_register_cb cb_datap_p={reason=vhpiCbValueChange obj=0x100000006:{vhpiSigDeclK Name=CK} cb_rtn=0x7f95163331a0 user_data=0x561053c17020} flags=1
VHPI: vhpi_disable_cb cb_obj=0x100000143:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_disable_cb cb_obj=0x100000144:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}
VHPI: vhpi_register_cb cb_datap_p={reason=vhpiCbAfterDelay obj=NULL cb_rtn=0x7f95163331a0 user_data=0x5610547a2790} flags=1
VHPI: vhpi_disable_cb cb_obj=0x100000144:{vhpiCallbackK Reason=vhpiCbValueChange State=vhpiEnable}

Can you raise an issue in the cocotb repository and see what they think? IMO it needs to call vhpi_remove_cb when it's done using the callback object.