$display(...) printing incorrect $time and old value of signal, different than displayed on waveform.

[dpikul]

Reposting, my other post was marked as spam and I'm not sure why.

Recently switched to 2019.1.2 and am seeing an issue I haven't seen before.

First issue is that $display tasks seem to be printing at unexpected times. Take the following example:

    always_ff@(posedge i_clk) begin : sm_sync
        if(i_clk_en) begin
            //do stuff
            //simple display of time and data
            $display("%t Input Data: %h", $time, bus.data);
        end 
    end

In this example, I would expect the time printed by the display task to match the time of the positive edge of the clock. However, instead the time of each display matches the NEGATIVE edge of the clock signal. See first screenshot. Every display seems to be getting triggered at the negative edge of the clock signal.

The other issue is that the value printed by each display (at each timestamp) is actually printing the value of the data signal at the PREVIOUS negative edge of the clock signal, as can also be seen in the waveform. The $display task prints:

26000 Input Data: 555555fb

However at 25500 (positive clock edge) the vaue of the data changed to d5555555.

The really odd part is the synthesisable RTL is working as expected; at t=26,500 a state machine detects the value as being d5555555, not 555555fb like the $display suggests.

Is this behavior expected? I don't remember things working this way previously, and unfortunately I don't have an old version of Vivado on hand to test with. Appreciate any help.

[dpikul]

Small update, I wanted to test what would happen if I moved the $display to its own block and clocked it on the negative edge of the clock. Result is that it prints at the exact same times, but now displays the correct value at said time. 

    always_ff@(negedge i_clk) begin : separate_print 
        $display("%t Input Data: %h", $time, bus.data);
    end 

[dpikul]

So I solved the $time issue by switching to $realtime or changing my sim clock period to a non-integer value. Unexpected but whatever. However now have ANOTHER issue which I discovered while debugging this.

Namely, calls to $display and $error in an else block cause the block to be triggered even if the if() condition is true, but ONLY in printouts and not on the waveform.

See following block of code:

always_comb begin : sm_comb
    state = CHECK_MAC_SOF;
    //.....
    ERROR = 'b0;
    case(state_r)
        STATE_0 : begin 
            //...
        end
        STATE_1 : begin 
            state = STATE_0;
            if(bus.data == {8'hD5, 8'h55, 8'h55, 8'h55} begin
                state = STATE_2;
            end 
            else begin 
                ERROR = 'b1;
                $error("%s: Received improperly formatted data.");
                $display("Error = %h", ERROR);
                $display("%h", bus.sof);
                $display("Rxd: %h", bus.data);
                $display("Exp: %h", {8'hD5, 8'h55, 8'h55, 8'h55});
                $display("%h", bus.length);
                //$finish();
            end 
        end 
        STATE_2 : begin 
            //...
        end

        ........

    endcase
end 

On the waveform, the ERROR signal is never asserted. However, everything within the ELSE block is executed, displaying the previous value of bus.data and showing that ERROR=1, as can be seen on the screenshots, where ERROR is never asserted in the wave, but the $error and $display statements execute anyway.

Now I understand why the $display statement shows the OLD value, it is related to verilog order of execution. My issue here is that putting $display or $error causes everything in both the IF, and the ELSE, to be executed simulatenously. If the IF condition holds true (which it does in my example), shouldn't the $display statements not even execute?