[Search for users]
[Overall Top Noters]
[List of all Conferences]
[Download this site]
| Title: | DECC |
| Notice: | General DEC C discussions |
| Moderator: | TLE::D_SMITH N TE |
|
| Created: | Fri Nov 13 1992 |
| Last Modified: | Fri Jun 06 1997 |
| Last Successful Update: | Fri Jun 06 1997 |
| Number of topics: | 2212 |
| Total number of notes: | 11045 |
2154.0. "Conditional fails intermittently using uint64 variables" by STAR::DEYOUNG () Wed Apr 16 1997 11:55
I'm not sure if this is a compiler bug or what the problem is but
apparently simple logic is failing to consistently execute.
I've got a C program that accesses the system's 100 nanosecond counter: .
I'm storing the value in a uint64 variable.
The problem I'm encountering is in a conditional.
What I've done is created a sampling data collector. Everytime a QIOW Delivery
AST is executed, the program checks to see if the sample period is over by
comparing the current time with the estimated end of the sampling period. The
estimate is generated upon completion of the last sample, except in the case
of the first sample. I also test to insure that the clock has not rolled over
(not assuming an initial value of zero for the clock at boot time. This may be
superfluos since the clock theoretically only rolls over once every 85,000 years! )
The problem is that the test occasionally fails. I've put printf's into the
code and the results are shown after the section of code.
I've had this program run for 10 minutes without failure and I've had it
fail after 5 seconds!
CODE @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
uint64 sample_period_in_nanos; /* */
uint64 current_time; /* time of last IO completion */
.
.
.
.
void ast_DELIVER_QIOW_FixSize_Sample()
{
current_time=EXE$GQ_SYSTIME; /* get completion time */
if (iosb[0].IO_status != SS$_NORMAL) /* function successful? */
{
if(pending_IO_function[0]) printf("Failure in QIO performing Write: iosb.status = %x", iosb[0].IO_status);
else printf("Failure in QIO performing Read: iosb.status = %x", iosb[0].IO_status);
sys$exit(iosb[0].IO_status); /* exit if not */
}
ios_completed++;
deltat = current_time - pending_io_start_time[0];
if(deltat < 1) deltat = 0xFFFFFFFFFFFFFFFF + deltat; /* clock rolls over every 4849 years but not assuming initial clock = 0 */
cumulativetime = cumulativetime + deltat;
if(pending_IO_function[0]) /* = 0:read, =1:write */ /* Update Per IO Size Data */
{
W_IO_COUNT[0] ++;
W_IO_TIME[0] = W_IO_TIME[0] + deltat;
}
else
{
R_IO_COUNT[0] ++;
R_IO_TIME[0] = R_IO_TIME[0] + deltat;
}
l++;
if((((uint64)current_time) > ((uint64)end_of_period))
&& ((((uint64)current_time) - ((uint64)end_of_period))<ROLLEDOVER)) /* save Sample results and update screen */
{
SAMPLE_INDEX++; /* INDEX always points to location before next free data slot */
sample_count++; /* increment count of all samples taken till now */
if(SAMPLE_INDEX==MAX_SAMPLES)SAMPLE_INDEX=0; /* rollover if at end of array */
IO_RATE[SAMPLE_INDEX]=(10000000*(ios_completed-last_iocount))/(current_time-start_of_period); /* Calculate throughput, save data for */
/* DIAGNOSTICS VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */
samplestart[SAMPLE_INDEX]=start_of_period;
sampleend[SAMPLE_INDEX]=current_time;
sampleendp[SAMPLE_INDEX]=end_of_period;
sampleiocount[SAMPLE_INDEX]=ios_completed-last_iocount;
samplecurcount[SAMPLE_INDEX]=ios_completed;
/* DIAGNOSTICS ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */
last_iocount = ios_completed; /* update last_iocount for next sample */
start_of_period = current_time; /* entering new sample: reset start of period */
end_of_period = start_of_period + sample_period_in_nanos; /* calculate end of next sample */
/* DIAGNOSTICS VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */
sampleendp[SAMPLE_INDEX+1]=end_of_period;
l=0;
printf("\n");
/* DIAGNOSTICS ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */
}
/* DIAGNOSTICS VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */
else if (((uint64)current_time) > ((uint64)end_of_period))
{
printf("C>P CT: %u EOP: %u DIFF: %u\n",current_time,end_of_period,current_time-end_of_period);
}
else if (l>130)
{
printf("l>130 CT: %u EOP: %u DIFF: %u\n",current_time,end_of_period,current_time-end_of_period);
}
/* DIAGNOSTICS ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */
return;
}
END OF CODE @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
(annotated) SCREEN OUTPUT FROM PROGRAM EXECUTION VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV
RUN N------------------------------------------
( These lines occur when more than 130 QIOs have been completed
within a sample period. (Just verifying my sanity...))
l>130 CT: 1975758646 EOP: 1976276831 DIFF: 4294449111
l>130 CT: 1976207836 EOP: 1976276831 DIFF: 4294898301
l>130 CT: 1986334141 EOP: 1986539846 DIFF: 4294761591
l>130 CT: 1996645981 EOP: 1996666151 DIFF: 4294947126
( This is where current_time (CT:) is
less than end_of_period (EOP:)
But the conditional:
else if (((uint64)current_time) > ((uint64)end_of_period))
evaluates to true which results in the following lines being printed.
/ \
/ \
/ \
/ \
/ \ )
C>P CT: 2147517966 EOP: 2147840851 DIFF: 4294644411
C>P CT: 2147859741 EOP: 2147840851 DIFF: 18890
C>P CT: 2148142926 EOP: 2147840851 DIFF: 302075
C>P CT: 2148387051 EOP: 2147840851 DIFF: 546200
C>P CT: 2148435876 EOP: 2147840851 DIFF: 595025
C>P CT: 2148543291 EOP: 2147840851 DIFF: 702440
C>P CT: 2148875301 EOP: 2147840851 DIFF: 1034450
C>P CT: 2149187781 EOP: 2147840851 DIFF: 1346930
C>P CT: 2149431906 EOP: 2147840851 DIFF: 1591055
C>P CT: 2149851801 EOP: 2147840851 DIFF: 2010950
C>P CT: 2149890861 EOP: 2147840851 DIFF: 2050010
( \ /
\ /
\ /
\ /
\ /
Here current_time (CT:) is
greater than end_of_period (EOP:)
But the conditional first conditional:
if((((uint64)current_time) > ((uint64)end_of_period))
&& ((((uint64)current_time) - ((uint64)end_of_period))<ROLLEDOVER))
^^^
(ROLLEDOVER=1000000000000)
.
.
.
.
.
I can provide the code and files necessary to duplicate this problem.
I have a .lis file as well, but not being fluent in macro, something's
eluding me. )
.LIS Excerpts @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
33706 if((((uint64)current_time) > ((uint64)end_of_period))
33707 && ((((uint64)current_time) - ((uint64)end_of_period))<ROLLEDOVER)) /* save Sample results and update scr
33707 een */
33708 {
33709 SAMPLE_INDEX++; /* INDEX always points to location before next fre
33709 e data slot */
33710 sample_count++; /* increment count of all samples taken till now
33710 */
33711 if(SAMPLE_INDEX==MAX_SAMPLES)SAMPLE_INDEX=0; /* rollover if at end of array */
33712 IO_RATE[SAMPLE_INDEX]=(10000000*(ios_completed-last_iocount))/(current_time-start_of_period); /* Calculate t
33712 hroughput, save data for */
33713 /*
33714 printf("SAMPLE_INDEX % 8i IO_RATE[SAMPLE_INDEX]% 8.1f \n",SAMPLE_INDEX,IO_RATE[SAMPLE_INDEX]);
33715 printf("SAMPLE_INDEX %i ios_completed: % 4i last_iocount: % 4i current_time: %u start_of_period: %u IO_RATE[SAMPL
33715 E_INDEX]%8.1f \n"
33716 ,SAMPLE_INDEX,ios_completed,last_iocount,current_time,start_of_period,IO_RATE[SAMPLE_INDEX]);
33717 */
33718 samplestart[SAMPLE_INDEX]=start_of_period;
33719 sampleend[SAMPLE_INDEX]=current_time;
33720 sampleendp[SAMPLE_INDEX]=end_of_period;
33721 sampleiocount[SAMPLE_INDEX]=ios_completed-last_iocount;
33722 samplecurcount[SAMPLE_INDEX]=ios_completed;
33723 last_iocount = ios_completed; /* update last_iocount for next sample */
33724 start_of_period = current_time; /* entering new sample: reset start of period */
33725 end_of_period = start_of_period + sample_period_in_nanos; /* calculate end of next sample */
33726 sampleendp[SAMPLE_INDEX+1]=end_of_period;
33727 l=0;
33728 printf("\n");
33729 }
33730 else if (((uint64)current_time) > ((uint64)end_of_period))
33731 {
33732 printf("C>P CT: %u EOP: %u DIFF: %u\n",current_time,end_of_period,current_time-end_of_period);
33733 }
33734 else if (l>130)
33735 {
33736 printf("l>130 CT: %u EOP: %u DIFF: %u\n",current_time,end_of_period,current_time-end_of_period);
33737 }
33738 return;
Machine Code Listing 11-APR-1997 13:49:20 DEC C V5.5-002 Page 125
AST_DELIVER_QIOW_FIXSIZE_SAMPLE 11-APR-1997 13:49:05 SYS$SYSDEVICE:[DEYOUNG.IO]IOHAMMER.C;217
A702FD28 454C LDQ R24, -728(R2) ; 033697
A742FE38 4550 LDQ R26, -456(R2) ; 033698
A3380000 4554 LDL R25, (R24) ; 033697
A77A0000 4558 LDQ R27, (R26) ; 033698
43203019 455C ADDL R25, 1, R25 ; 033697
4363041B 4560 ADDQ R27, R3, R27 ; 033698
B3380000 4564 STL R25, (R24) ; 033697
B77A0000 4568 STQ R27, (R26) ; 033698
C3E00008 456C BR L$512 ; 033700
4570 L$511:
A4A2FD00 4570 LDQ R5, -768(R2) ; 033703
A402FE00 4574 LDQ R0, -512(R2) ; 033702
A6A50000 4578 LDQ R21, (R5) ; 033703
A2200000 457C LDL R17, (R0) ; 033702
42A30403 4580 ADDQ R21, R3, R3 ; 033703
B4650000 4584 STQ R3, (R5)
42203011 4588 ADDL R17, 1, R17 ; 033702
B2200000 458C STL R17, (R0)
4590 L$512: ; 033704
A6E2FD60 4590 LDQ R23, -672(R2) ; 033705
A682FF68 4594 LDQ R20, -152(R2) ; 033706
A7020028 4598 LDQ R24, 40(R2) ; 033707
A2170000 459C LDL R16, (R23) ; 033705
A4340000 45A0 LDQ R1, (R20) ; 033706
A7180000 45A4 LDQ R24, ROLLEDOVER ; R24, (R24) ; 033707
42003012 45A8 ADDL R16, 1, R18 ; 033705
B2570000 45AC STL R18, (R23)
408107B3 45B0 CMPULE R4, R1, R19 ; 033706
A6A2FE30 45B4 LDQ R21, -464(R2) ; 033709
F6600053 45B8 BNE R19, L$516 ; 033706
40810533 45BC SUBQ R4, R1, R19 ; 033707
427803B8 45C0 CMPULT R19, R24, R24
A7220020 45C4 LDQ R25, 32(R2) ; 033712
E700004A 45C8 BEQ R24, L$520 ; 033707
A0150000 45CC LDL R0, (R21) ; 033709
A602FCB0 45D0 LDQ R16, -848(R2) ; 033718
A3590000 45D4 LDL R26, (R25) ; 033712
40003000 45D8 ADDL R0, 1, R0 ; 033709
A4E2FEC0 45DC LDQ R7, -320(R2) ; 033722
2220F1F0 45E0 ADDQ R0, -3600, R17 ; 033711
A702FEB0 45E4 LDQ R24, -336(R2) ; 033719
46201480 45E8 CMOVEQ R17, 0, R0 ; 033711
42DA013A 45EC SUBL R22, R26, R26 ; 033712
401F0245 45F0 S8ADDL R0, R31, R5 ; 033718
48A1F633 45F4 ZAPNOT R5, 15, R19
47E00403 45F8 MOV R0, R3 ; 033711
B0750000 45FC STL R3, (R21)
401F0245 4600 S8ADDL R0, R31, R5 ; 033720
A402FC98 4604 LDQ R0, -872(R2)
42130410 4608 ADDQ R16, R19, R16 ; 033718
A6A2FCA0 460C LDQ R21, -864(R2) ; 033721
48A1F631 4610 ZAPNOT R5, 15, R17 ; 033719
48A1F625 4614 ZAPNOT R5, 15, R5 ; 033720
407F0053 4618 S4ADDL R3, R31, R19 ; 033722
4B40F73B 461C SLL R26, 7, R27 ; 033712
4A61F626 4620 ZAPNOT R19, 15, R6 ; 033721
4A61F633 4624 ZAPNOT R19, 15, R19 ; 033722
-Mark (Star::Deyoung X11556)
| T.R | Title | User | Personal
Name | Date | Lines |
|---|
| 2154.1 | Perhaps you have the wrong printf format? | CXXC::REINIG | This too shall change | Wed Apr 16 1997 12:38 | 18 |
| I notice that when you are printing out current_time and end_of_period
you are using %u.
printf("C>P CT: %u EOP: %u DIFF: %u\n",
current_time,
end_of_period,
current_time-end_of_period);
Since current_time is a uint64
uint64 current_time
you should be using %Lu (or %llu) to print this out. This would apply to
other uint64 values.
If you make this change, does the problem remain?
August G. Reinig
|
| 2154.2 | Getting closer | STAR::DEYOUNG | | Thu Apr 17 1997 18:26 | 37 |
| I've modified my printf statements and am experimenting with a modified
format statement and am obtaining interesting results.
Using printf statements of the following form:
printf("C>P CT: %Lu EOP: %Lu DIFF: %Lu\n"
,current_time,end_of_period,current_time-end_of_period);
printf("C>P CT: %0X EOP: %0X DIFF: %0X\n"
,current_time,end_of_period,current_time-end_of_period);
printf("C>P CT: %08X %08X EOP: %08X %08X DIFF: %08X %08X\n"
,current_time,end_of_period,current_time-end_of_period);
I've obtained the following glimpse of the 'failure'
.
.
.
SAMPLE 20 CT: 18446744073692399689 EOP: 18446744073692371034 DIFF: 28655
SAMPLE 20 CT: 00000000FEFA4849 EOP: 00000000FEF9D85A DIFF: 0000000000006FEF
SAMPLE 20 CT: FFFFFFFF FEFA4849 EOP: FFFFFFFF FEF9D85A DIFF: 00000000 00006FEF
SAMPLE 21 CT: 18446744073702408814 EOP: 18446744073702399689 DIFF: 9125
SAMPLE 21 CT: 00000000FF93026E EOP: 00000000FF92DEC9 DIFF: 00000000000023A5
SAMPLE 21 CT: FFFFFFFF FF93026E EOP: FFFFFFFF FF92DEC9 DIFF: 00000000 000023A5
C>P CT: 18446744073702740824 EOP: 2857198 DIFF: 18446744073699883626
C>P CT: FF981358 EOP: 2B98EE DIFF: FF6C7A6A
C>P CT: FFFFFFFF FF981358 EOP: 00000000 002B98EE DIFF: FFFFFFFF FF6C7A6A
C>P CT: 18446744073703492729 EOP: 2857198 DIFF: 18446744073700635531
C>P CT: FFA38C79 EOP: 2B98EE DIFF: FF77F38B
C>P CT: FFFFFFFF FFA38C79 EOP: 00000000 002B98EE DIFF: FFFFFFFF FF77F38B
.
.
.
- I thought this was simple unsigned integer math... Boy was I wrong.
:^) - Mark
The problem may be occurring as the result of the line where I add the
sample_period to the current_time to obtain the end_of_period.
|
| 2154.3 | | WIBBIN::NOYCE | Pulling weeds, pickin' stones | Thu Apr 17 1997 18:41 | 2 |
| How is EXE$GQ_SYSTIME declared? It looks as if you've declared it as an
unsigned 32-bit type.
|
| 2154.4 | | COMEUP::SIMMONDS | loose canon | Thu Apr 17 1997 21:31 | 11 |
| Re: .3
Bill, that's what I thought too, but .0 says:
.0> I've had this program run for 10 minutes without failure and I've had it
.0> fail after 5 seconds!
so, if our conjecture is true, then the longest interval between glitches
should only be 429.5 seconds or ~ 7 minutes.
John.
|
| 2154.5 | volatile, atomic? | CUJO::SAMPSON | | Thu Apr 17 1997 22:22 | 8 |
| Re .*
EXE$GQ_SYSTIME should be declared "volatile" of course,
and it also occurs to me that you may have to use the built-in
atomic quadword read on it, in order to always get a consistent
quadword value.
FWIW
|
| 2154.6 | | GEMEVN::GLOSSOP | Only the paranoid survive | Thu Apr 17 1997 22:30 | 1 |
| volatile is sufficient for getting an atomic read for scalars.
|
| 2154.7 | Try %LX | DECCXL::WIBECAN | That's the way it is, in Engineering! | Fri Apr 18 1997 10:48 | 33 |
| >> printf("C>P CT: %Lu EOP: %Lu DIFF: %Lu\n"
>> ,current_time,end_of_period,current_time-end_of_period);
This print format prints three 64 bit unsigned integers.
>> printf("C>P CT: %0X EOP: %0X DIFF: %0X\n"
>> ,current_time,end_of_period,current_time-end_of_period);
This print format prints three 32 bit integers in hex.
>> printf("C>P CT: %08X %08X EOP: %08X %08X DIFF: %08X %08X\n"
>> ,current_time,end_of_period,current_time-end_of_period);
These print format prints six 32 bit integers in hex, of which you provide
three.
You should use forms of %LX for printing 64 bit integers in hex:
uint64 a = 0x8badf00ddeadbeefL;
printf ("%%Lu %Lu\n", a);
printf ("%%0X %0X\n", a);
printf ("%%8X %8X\n", a);
printf ("%%0LX %0LX\n", a);
printf ("%%16LX %16LX\n", a);
yields
%Lu 10064964684604096239
%0X DEADBEEF
%8X DEADBEEF
%0LX 8BADF00DDEADBEEF
%16LX 8BADF00DDEADBEEF
|
| 2154.8 | Thanks for all the help: you guessed it! | STAR::DEYOUNG | | Fri Apr 18 1997 14:48 | 13 |
| Yup, my friend and I guessed that it was the improper
declaration of exe$gq_system. Being a relative novice
in C, I did not understand that the advice I was given
initially had a certain level of understanding assumed,
and not having that, I coded the improper my statement-
extern EXE$GQ_SYSTIME;
which resulted in it being compiled as an int.
A little more research on my part would have avoided
wasting your time as well as my own.
Not to try to deflect responsability, but I am curious
that the statement did not produce a warning by
the compliler. Is this because of extrordinary flexability
of C?
|
| 2154.9 | Power of assembly language + convenience of assembly language | WIBBIN::NOYCE | Pulling weeds, pickin' stones | Fri Apr 18 1997 15:18 | 1 |
| If a syntactically-legal declaration doesn't give a datatype, it gets "int".
|