Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timeout Error #299

Closed
alinaivanovaoff opened this issue Jan 16, 2018 · 27 comments
Closed

Timeout Error #299

alinaivanovaoff opened this issue Jan 16, 2018 · 27 comments

Comments

@alinaivanovaoff
Copy link

alinaivanovaoff commented Jan 16, 2018

Hi,
My testbench is:

`timescale 1 ns / 1 ps
`include "vunit_defines.svh"
module vunit_test_tb  ();
    parameter CLOCK                          = 12.5;
// Clock
    var clk;
    logic rstn;
    logic [15:0] data_in;
    initial begin
        clk = 1;
        forever begin
            #(CLOCK / 2.0) clk               = ~clk;
        end
    end

    `TEST_SUITE begin
        `TEST_SUITE_SETUP begin
            $display("Running test suite setup code");
            rstn = 0;
            data_in = 0;
            #10;
            rstn = 1;
        end

        `TEST_CASE("Test_pass") begin
            $display("This test case is expected to pass");
            `CHECK_EQUAL(data_in, 0);
        end

        `TEST_CASE("Test_fail") begin
            $display("This test case is expected to fail");
            `CHECK_EQUAL(data_in, 10);
            $stop();
        end
    end;

    `WATCHDOG(1us);
endmodule

My Python script is:

from vunit.verilog import VUnit
vu = VUnit.from_argv()
lib = vu.add_library("lib")
lib.add_source_files("../tb/vunit_tb.sv")
vu.main()

I got a timeout error:

# Running test suite setup code
# ** Error: Timeout waiting finish after 1.000 ns
#    Time: 1 ns  Scope: vunit_pkg.test_runner.watchdog.wait_or_timeout File: C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 218
# Break in Task vunit_pkg/test_runner::watchdog at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# Stopped at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# 
# Stack trace result from 'tb' command
#  C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 218 [address f8249183] Task vunit_pkg/test_runner::watchdog
# 
# 
# Surrounding code from 'see' command
#   213 : 
#   214 :    task automatic watchdog(realtime timeout);
#   215 :       fork : wait_or_timeout
#   216 :          begin
#   217 :             #timeout;
# ->218 :             $error("Timeout waiting finish after %.3f ns", timeout / 1ns);
#   219 :             disable wait_or_timeout;
#   220 :          end
#   221 :          begin
#   222 :             @(posedge exit_without_errors);
# 
fail (P=0 S=0 F=1 T=5) lib.vunit_test_tb.Test_pass (3.1 seconds)

Starting lib.vunit_test_tb.Test_fail
Output file: D:\Projects\rebuf_cat_mem\vunit_test\sim\vunit_out\test_output\lib.vunit_test_tb.Test_fail_089e0492b9fc7534feac61c9effcb400480954aa\output.txt
# vsim 
# Start time: 10:25:41 on Jan 16,2018
# ** Note: (vsim-3812) Design is being optimized...
# 
# Running test suite setup code
# ** Error: Timeout waiting finish after 1.000 ns
#    Time: 1 ns  Scope: vunit_pkg.test_runner.watchdog.wait_or_timeout File: C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 218
# Break in Task vunit_pkg/test_runner::watchdog at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# Stopped at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# 
# Stack trace result from 'tb' command
#  C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 218 [address f8249183] Task vunit_pkg/test_runner::watchdog
# 
# 
# Surrounding code from 'see' command
#   213 : 
#   214 :    task automatic watchdog(realtime timeout);
#   215 :       fork : wait_or_timeout
#   216 :          begin
#   217 :             #timeout;
# ->218 :             $error("Timeout waiting finish after %.3f ns", timeout / 1ns);
#   219 :             disable wait_or_timeout;
#   220 :          end
#   221 :          begin
#   222 :             @(posedge exit_without_errors);
# 
fail (P=0 S=0 F=2 T=5) lib.vunit_test_tb.Test_fail (1.8 seconds)

Starting lib.vunit_test_tb.Test that a successful test case passes
Output file: D:\Projects\rebuf_cat_mem\vunit_test\sim\vunit_out\test_output\lib.vunit_test_tb.Test_that_a_successful_test_case_passes_f8826b061b59aca9a4e68e9e7f7b09bdfce31593\output.txt
# vsim 
# Start time: 10:25:43 on Jan 16,2018
# ** Note: (vsim-3812) Design is being optimized...
# 
# ** Error: Found no "Test that a successful test case passes" test case
#    Time: 0 ps  Scope: vunit_pkg.test_runner.loop File: C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 160
# Break in Function vunit_pkg/test_runner::loop at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# Stopped at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# 
# Stack trace result from 'tb' command
#  C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 160 [address f8247ceb] Function vunit_pkg/test_runner::loop
# called from  D:/Projects/rebuf_cat_mem/vunit_test/tb/vunit_tb.sv 19 [address f824aa6d]  
# 
# 
# Surrounding code from 'see' command
#   155 :                      found = 1;
#   156 :                      break;
#   157 :                   end
#   158 :                end
#   159 :                if (!found) begin
# ->160 :                   $error("Found no \"%s\" test case", test_cases_to_run[j]);
#   161 :                   cleanup();
#   162 :                   return 0;
#   163 :                end
#   164 :             end
# 
fail (P=0 S=0 F=3 T=5) lib.vunit_test_tb.Test that a successful test case passes (1.8 seconds)

Starting lib.vunit_test_tb.Test that a failing test case actually fails
Output file: D:\Projects\rebuf_cat_mem\vunit_test\sim\vunit_out\test_output\lib.vunit_test_tb.Test_that_a_failing_test_case_actually_f0cb1e66cd2b634b4b8acbba98c5afdc07ed55577\output.txt
# vsim 
# Start time: 10:25:45 on Jan 16,2018
# ** Note: (vsim-3812) Design is being optimized...
# 
# ** Error: Found no "Test that a failing test case actually fails" test case
#    Time: 0 ps  Scope: vunit_pkg.test_runner.loop File: C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 160
# Break in Function vunit_pkg/test_runner::loop at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# Stopped at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# 
# Stack trace result from 'tb' command
#  C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 160 [address f8247ceb] Function vunit_pkg/test_runner::loop
# called from  D:/Projects/rebuf_cat_mem/vunit_test/tb/vunit_tb.sv 19 [address f824aa6d]  
# 
# 
# Surrounding code from 'see' command
#   155 :                      found = 1;
#   156 :                      break;
#   157 :                   end
#   158 :                end
#   159 :                if (!found) begin
# ->160 :                   $error("Found no \"%s\" test case", test_cases_to_run[j]);
#   161 :                   cleanup();
#   162 :                   return 0;
#   163 :                end
#   164 :             end
# 
fail (P=0 S=0 F=4 T=5) lib.vunit_test_tb.Test that a failing test case actually fails (1.8 seconds)

Starting lib.vunit_test_tb.Test that a test case that takes too long time fails with a timeout
Output file: D:\Projects\rebuf_cat_mem\vunit_test\sim\vunit_out\test_output\lib.vunit_test_tb.Test_that_a_test_case_that_takes_too_lon95f1b0550c233d3e1e6e0a77fee1c1bbbc054df8\output.txt
# vsim 
# Start time: 10:25:46 on Jan 16,2018
# ** Note: (vsim-3812) Design is being optimized...
# 
# ** Error: Found no "Test that a test case that takes too long time fails with a timeout" test case
#    Time: 0 ps  Scope: vunit_pkg.test_runner.loop File: C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 160
# Break in Function vunit_pkg/test_runner::loop at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# Stopped at C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 160
# 
# Stack trace result from 'tb' command
#  C:/Program Files/Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 160 [address f8247ceb] Function vunit_pkg/test_runner::loop
# called from  D:/Projects/rebuf_cat_mem/vunit_test/tb/vunit_tb.sv 19 [address f824aa6d]  
# 
# 
# Surrounding code from 'see' command
#   155 :                      found = 1;
#   156 :                      break;
#   157 :                   end
#   158 :                end
#   159 :                if (!found) begin
# ->160 :                   $error("Found no \"%s\" test case", test_cases_to_run[j]);
#   161 :                   cleanup();
#   162 :                   return 0;
#   163 :                end
#   164 :             end
# 
fail (P=0 S=0 F=5 T=5) lib.vunit_test_tb.Test that a test case that takes too long time fails with a timeout (1.8 seconds)

==== Summary =================================================================================================
fail lib.vunit_test_tb.Test_pass                                                           (3.1 seconds)
fail lib.vunit_test_tb.Test_fail                                                           (1.8 seconds)
fail lib.vunit_test_tb.Test that a successful test case passes                             (1.8 seconds)
fail lib.vunit_test_tb.Test that a failing test case actually fails                        (1.8 seconds)
fail lib.vunit_test_tb.Test that a test case that takes too long time fails with a timeout (1.8 seconds)
==============================================================================================================
pass 0 of 5
fail 5 of 5
==============================================================================================================
Total time was 10.2 seconds
Elapsed time was 10.5 seconds
==============================================================================================================
Some failed!

As I understand ``WATCHDOG(1us);` is set timeout, but why I get an error, I have a stop on 36 line?
My next question: Why does summary show five tests instead of two?
Could you help me, please?

@kraigher
Copy link
Collaborator

Regarding the extra tests. Sure they are not commented out but still in the file? As I said on Gitter we did not ignore commented out tests in SystemVerilog before, I fixed that in 2.4.0 but you need to update VUnit.

@kraigher
Copy link
Collaborator

Also sure there is no duplicate modules named vunit_test_tb? It should be warning when you add duplicates to run.py.

@alinaivanovaoff
Copy link
Author

alinaivanovaoff commented Jan 16, 2018

Could I have such module in another file, but not included in the python script?

@alinaivanovaoff
Copy link
Author

I have updated VUnit version. Now I have two tests. It solved, thank you @kraigher.

@alinaivanovaoff
Copy link
Author

I still have a problem with a timeout.
Error Message:

# Running test suite setup code
# ** Error: Timeout waiting finish after 1.000 ns
#    Time: 1 ns  Scope: vunit_pkg.test_runner.watchdog.wait_or_timeout File: ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 218
# Break in Task vunit_pkg/test_runner::watchdog at ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# Stopped at ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# 
# Stack trace result from 'tb' command
#  ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 218 [address f8249183] Task vunit_pkg/test_runner::watchdog
# 
# 
# Surrounding code from 'see' command
#   213 : 
#   214 :    task automatic watchdog(realtime timeout);
#   215 :       fork : wait_or_timeout
#   216 :          begin
#   217 :             #timeout;
# ->218 :             $error("Timeout waiting finish after %.3f ns", timeout / 1ns);
#   219 :             disable wait_or_timeout;
#   220 :          end
#   221 :          begin
#   222 :             @(posedge exit_without_errors);
# 
fail (P=0 S=0 F=1 T=2) lib.vunit_test_tb.Test_pass (3.0 seconds)

Starting lib.vunit_test_tb.Test_fail
Output file: vunit_out\test_output\lib.vunit_test_tb.Test_fail_089e0492b9fc7534feac61c9effcb400480954aa\output.txt
# vsim 
# Start time: 13:05:51 on Jan 16,2018
# ** Note: (vsim-8009) Loading existing optimized design _opt
# 
# Running test suite setup code
# ** Error: Timeout waiting finish after 1.000 ns
#    Time: 1 ns  Scope: vunit_pkg.test_runner.watchdog.wait_or_timeout File: ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv Line: 218
# Break in Task vunit_pkg/test_runner::watchdog at ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# Stopped at ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv line 218
# 
# Stack trace result from 'tb' command
#  ../Python36/lib/site-packages/vunit/verilog/vunit_pkg.sv 218 [address f8249183] Task vunit_pkg/test_runner::watchdog
# 
# 
# Surrounding code from 'see' command
#   213 : 
#   214 :    task automatic watchdog(realtime timeout);
#   215 :       fork : wait_or_timeout
#   216 :          begin
#   217 :             #timeout;
# ->218 :             $error("Timeout waiting finish after %.3f ns", timeout / 1ns);
#   219 :             disable wait_or_timeout;
#   220 :          end
#   221 :          begin
#   222 :             @(posedge exit_without_errors);
# 
fail (P=0 S=0 F=2 T=2) lib.vunit_test_tb.Test_fail (1.6 seconds)

==== Summary =======================================
fail lib.vunit_test_tb.Test_pass (3.0 seconds)
fail lib.vunit_test_tb.Test_fail (1.6 seconds)
====================================================
pass 0 of 2
fail 2 of 2
====================================================
Total time was 4.6 seconds
Elapsed time was 4.9 seconds
====================================================
Some failed!

@kraigher
Copy link
Collaborator

** Error: Timeout waiting finish after 1.000 ns

The timeout says 1.000 ns? Is that 1000 ns or 1 ns?

@kraigher
Copy link
Collaborator

The display statement in the TEST_SUITE_SETUP is reached but it contains a wait for 10 ns.

@alinaivanovaoff
Copy link
Author

I have set WATCHDOG(1us) - should be one microsecond.

@kraigher
Copy link
Collaborator

Yes I see that but maybe there is a bug in the watchdog.

@kraigher
Copy link
Collaborator

This is how it looks like.

`define WATCHDOG(runtime) \
   initial begin \
      __runner__.watchdog(runtime); \
   end


   task automatic watchdog(realtime timeout);
      fork : wait_or_timeout
         begin
            #timeout;
            $error("Timeout waiting finish after %.3f ns", timeout / 1ns);
            disable wait_or_timeout;
         end
         begin
            @(posedge exit_without_errors);
            disable wait_or_timeout;
         end
      join
   endtask;

@kraigher
Copy link
Collaborator

I guess #timeout in the watchdog does not work as intended.

@alinaivanovaoff
Copy link
Author

alinaivanovaoff commented Jan 16, 2018

I can suggest something like this one:

fork
    begin
       //test
    end
    begin
       while ($time < TIMEOUT) begin
           @(posedge clk);
       end
       $error("Timeout over");
    end
join_any
disable fork

@kraigher
Copy link
Collaborator

I do not like your suggestion since it depends on a signal named clk. Surely there must be a way in SystemVerilog to wait for a fixed time without knowing the timescale.

@alinaivanovaoff
Copy link
Author

Yes, it should be a synchronous process and better to know time scale.

@alinaivanovaoff
Copy link
Author

alinaivanovaoff commented Jan 16, 2018

If you need asynchronous process:

fork
    begin
       //test
    end
    begin
       #TIMEOUT;
       $error("Timeout over");
    end
join_any
disable fork

@svenka3
Copy link

svenka3 commented Jan 16, 2018

To make the watchdog code async and independent of timescale - use explicit time unit in the wait statement.

Below is a piece of code that we've in Go2OVM lib doing similar thing - in this case it waits for a signal or a predefined time and exits

You may want to try that.

Then user can supply arg in multiples of NS.

`define GO2OVM_WAIT(END_SIG, WDOG_VAL = GO2OVM_WDOG_DEL_IN_NS) \
fork \
begin \
string msg; \
wait (END_SIG); \
msg = $sformatf ("Wait seen in condition: %s ", `GO2OVM_DISP_ARG(END_SIG) ); \
`g2o_display (msg); \
end \
begin \
string msg; \
#(WDOG_VAL * 1ns); \
msg = $sformatf ("WDOG expired after waiting for: %0d %s %s", WDOG_VAL, "ns Wait condition: ", `GO2OVM_DISP_ARG(END_SIG) ); \
`g2o_error (msg); \
end \
join_any \
disable fork; 

@kraigher
Copy link
Collaborator

@alinaivanovaoff @svenka3 I pushed a fix for this to master now. See the referenced commit.

@alinaivanovaoff
Copy link
Author

@kraigher Is it now timeout time is "real", not "realtime"? If, yes, it is not suitable for my our coding style. It's not a problem, but I will not use `WATCHDOG.

@kraigher
Copy link
Collaborator

Ok what is the problem with real? When I divided the value by 1 ns it became a ratio and not an absolute time so I thought real was more appropriate.

@alinaivanovaoff
Copy link
Author

alinaivanovaoff commented Jan 17, 2018

Should I set in real or in realtime? According to our coding style, we set timeout in terms of realtime. It's more readable and there is information about timescale.

@kraigher
Copy link
Collaborator

The macro argument is still semantically realtime. Inside the macro the realtime is divided with 1ns to get a ration which is real. Thus you should use a realtime such as "1us" as the argument before. The macro interface has not changed only the implementation to fix the bug that you discovered when the timescale of the test bench differed from the timescale used in vunit_pkg.

In verilog it seems realtime such as 1ns is just a number relative the timescale. Thus if I passed 1ns realtime from testbench to vunit_pkg it caused a different delay if different timescales are used in the files. Strange semantics of verilog that a literal such as 1ns is not an absolute time.

@svenka3
Copy link

svenka3 commented Jan 17, 2018

@kraigher - nice fix. Few small notes/clarifications (for other readers perhaps):

Your fix is correct in my understanding.

Strange semantics of verilog that a literal such as 1ns is not an absolute time

I beg to differ - it is absolute, but when used in a # context - it gets evaluated with the timescale in effect. To clarify - in your new fix, you have:

time_val / 1ns --> That's absolute 1ns

In @alinaivanovaoff original use case - she/he has:
`WATCHDOG(1us)

That 1us is absolute - and gets scaled to a time unit when used with a #

I have seen few more complications with class and this 1ns code - lucky you don't see it for now!

Regards
Srini

@kraigher
Copy link
Collaborator

kraigher commented Jan 17, 2018

@svenka3

I beg to differ - it is absolute, but when used in a # context - it gets evaluated with the timescale in effect.

I am not convinced. To me it seems a time literal such as 1us is never stored as an absolute time but is directly converted to a relative numeric value based on the local timescale. Thus if I pass a literal 1us to a package function and the package does not have the same timescale it cannot know the absolute time intended by the caller. It seems this can only be solved using a macro in Verilog where the time is normalized locally in the file before making a call. Vice versa this would mean that a time constant defined in a package would not be directly usable in other code that has a different timescale. I think this is less than optimal language semantics. I guess the lesson to learn is to avoid setting local timescale in Verilog.

Consider the following experiment as proof:
File module.sv

`timescale 1 ns / 1ps

module my_module;
   import my_pkg::*;

   initial begin
      realtime timeval = 1us;
      $display("my_module:timeval = %t", timeval);
      pkg_display(timeval);
   end;
endmodule;

File pkg.sv

package my_pkg;
   function automatic pkg_display(realtime timeval);
      if (timeval == 1us)
        $display("my_pkg:timeval == 1us");
      else
        $display("my_pkg:timeval != 1us");

      $display("my_pkg:timeval = %t, 1us = %t", timeval, 1us);
   endfunction
endpackage

output

# my_module:timeval = 1000000
# my_pkg:timeval != 1us
# my_pkg:timeval = 1000, 1us = 1000000

@alinaivanovaoff
Copy link
Author

If I want to add separate timeouts to each test case, what I should do?

@alinaivanovaoff
Copy link
Author

For example, each test case is test class:

    `TEST_SUITE begin
        `TEST_CASE("Test_pass") begin
            Test1 = new(usys, udata);
            Test1.pre_test();
            fork
                Test1.run();
                Test1.test_timeout(usys.clk, test_fail);
            join_any
            @(posedge usys.clk);
            disable fork;
            `CHECK_EQUAL(test_fail, 0);
        end
        `TEST_CASE("Test_pass") begin
            Test2 = new(usys, udata);
            Test2.pre_test();
            fork
                Test2.run();
                Test2.test_timeout(usys.clk, test_fail);
            join_any
            @(posedge usys.clk);
            disable fork;
            `CHECK_EQUAL(test_fail, 0);
        end
    end;

It this example I use my timout task.

@kraigher
Copy link
Collaborator

It is nothing in VUnit stopping you from using your own timeout task. The watchdog is optional. Maybe we could add a timeout that can be forked off from the main process.

@kraigher
Copy link
Collaborator

The WATCHDOG bugfix is available in release 2.4.1

nathanaelhuffman pushed a commit to nathanaelhuffman/vunit that referenced this issue Jul 30, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants