Merge ~bhill/epics-base:db-tpro-show-values into epics-base:3.16

[Bruce Hill]

Add diagnostic support for showing record values when TPRO is >= 2

[mdavidsaver (mdavidsaver)]

See previous discussion at https://github.com/epics-base/epics-base/pull/20

I personally like the idea of using TPRO to control debug prints. So much so that I've been adding it to my drivers so the last couple of years.

I don't have a problem with overloading TPRO in this way in Base. I would make the threshold numbers it larger (5 and 10).

As this is Base, maybe we should add a new field instead? Is .DDBG taken (aka Device support DeBuG)?

[Ralph Lange (ralph-lange)]

I like the idea of separating the Device Support debug setting from Record Support debug setting (as I had stated in the GitHub discussion), so I would be in favor of a new field, and DDBG sounds good as a name.

Larger threshold values sound like a good idea.

I don't understand why the aSub does not get the VAL printed, and the message might be misleading (as OUTx are the output links, not the output values).
Also, for a debug function, I would expect it to print VALx values independent from the event posting setting. (As with all records that don't have such a setting.)

bi/bo should IMHO always print the numerical value, and add the string if ONAM/ZNAM are defined.

mbbi/mbbo should add the string representation if there is one defined.

For many record types, when used with other than Soft Device Support, the RVAL field is as interesting as the VAL field.

aai/aao/compress/dfanout/event/histogram/int64in/int64out/lsi/lso/mbbiDirect/mbboDirect/permissive/sel/seq/state/stringin/stringout/subArray/sub/waveform are missing.

review: Needs Fixing

[Andrew Johnson (anj)]

A Google search for "EPICS TPRO" came back with a tech-talk discussion:
  https://epics.anl.gov/tech-talk/2014/msg00129.php
This thread contained a response from me contrary to my github answer:

> I do like the idea of using TPRO > 1 to trigger debug messages from
> record processing, and this could also be used by device support. It
> should be up to the specific record/device support to document its usage
> though.

While writing that response in 2014 I also adjusted the Wiki description at
  https://wiki-ext.aps.anl.gov/epics/index.php/RRM_3-14_dbCommon
to say:

> If this field is non-zero a message is printed whenever this record is
> processed, and when any other record in the same lock-set is processed
> by a database link from this record.

Thus (following the legal principle of stare decisis) I rescind my github objection to the use of TPRO to enable debug messages, but I would like to see some kind of standardization in the values used, either globally or at least by the record type. If we're going to do this though we should also do all the record types in Base, not just the ones we use/like the most.

Question: Should the TPRO value be a verbosity level, page selector, a bit-mask or some combination of the 3?

I support Ralph's comments about the record-specific behaviors. The VAL field of an aSub record holds the status value returned by the subroutine and is less useful than that of a sub record, so I can understand not being interested in seeing that (printing SNAM when it changes would be useful though). The seq record has an even less useful VAL field, and I'm sure there are others like it so I think that what gets printed should be up to the record type.

Setting TPRO on a record also prints the record names of any other records in the same lockset that are processed directly by the record, but it does not change their TPRO fields, so those records will not have their debug print mechanisms triggered (unless they also have TPRO set). This is still reasonable behavior.

Setting TPRO to 255 could be used for a DOS attack if it results in a lot of output. We are probably already serializing all our record processing when TPRO is set though (through printing the record name to stdout in the dbProcess() routine) but this is really just another attack surface of which we already have too many for this to change.

review: Needs Fixing

[Ralph Lange (ralph-lange)]

> Question: Should the TPRO value be a verbosity level, page selector, a bit-mask or some combination of the 3?

Bit-masks may make sense in device support debugging that is often distributed over multiple layers - see ASYN's trace masks.

Record support is practically always one layer, and I see a verbosity level being more useful.

If we split Device Support debugging to a separate field, each device support can use it as it prefers: mask or page or level. In that case I would support TPRO being a verbosity level.

If TPRO is shared between Record and Device Support, things get messy.

[mdavidsaver (mdavidsaver)]

> Question: Should the TPRO value be a verbosity level, page selector, a bit-mask or some combination of the 3?

I've only used it as a verbosity level, aka. print if TPRO>=N for some value of N.

[Bruce Hill (bhill)]

I've found uses of TPRO as a verbosity level in several device support modules along w/ some that just enable
diagnostics for any non-zero tpro value.     That was what I was looking to do w/ this commit.

On 03/13/2018 08:12 AM, mdavidsaver wrote:
>> Question: Should the TPRO value be a verbosity level, page selector, a bit-mask or some combination of the 3?
> I've only used it as a verbosity level, aka. print if TPRO>=N for some value of N.

--
Bruce Hill
Member Technical Staff
SLAC National Accelerator Lab
2575 Sand Hill Road M/S 10
Menlo Park, CA 94025

[Andrew Johnson (anj)]

Core Meeting: Should be done for (and messages consistent from) all record types; TPRO value of 1 should be reserved for just the current trace processing, values for these messages should be sensible (higher numbers may print more stuff, leave room between numbers for device support, link support etc. to use as well); consider adding another message when beginning/ending an asynchronous I/O operation.

review: Needs Fixing

Unmerged commits

e13659d... by Bruce Hill on 2017-02-18

Add diagnostic support for showing record values when TPRO is >= 2

diff --git a/src/std/rec/aSubRecord.c b/src/std/rec/aSubRecord.c
index b7d2286..608d54b 100644
--- a/src/std/rec/aSubRecord.c
+++ b/src/std/rec/aSubRecord.c
@@ -429,6 +429,8 @@ static void monitor(aSubRecord *prec)
             if (nev != onv || memcmp(povl, pval, alen)) {
                 memcpy(povl, pval, alen);
                 db_post_events(prec, pval, monitor_mask);
+                if ( prec->tpro >= 5 )
+                    printf( "%s.OUT%c changed!\n", prec->name, 'A' + i );
                 if (nev != onv) {
                     *ponv = nev;
                     db_post_events(prec, pnev, monitor_mask);
diff --git a/src/std/rec/aiRecord.c b/src/std/rec/aiRecord.c
index 81f730f..e7c0377 100644
--- a/src/std/rec/aiRecord.c
+++ b/src/std/rec/aiRecord.c
@@ -167,6 +167,10 @@ static long process(struct dbCommon *pcommon)
 	if (status==0) convert(prec);
 	else if (status==2) status=0;
 
+	if ( prec->tpro >= 2 )
+		printf( "%s: Process %s, val %f\n",
+			epicsThreadGetNameSelf(), prec->name, prec->val );
+
 	/* check for alarms */
 	checkAlarms(prec,&timeLast);
 	/* check event list */
diff --git a/src/std/rec/aoRecord.c b/src/std/rec/aoRecord.c
index 0d923af..defd6a4 100644
--- a/src/std/rec/aoRecord.c
+++ b/src/std/rec/aoRecord.c
@@ -197,6 +197,10 @@ static long process(struct dbCommon *pcommon)
 		prec->udf = isnan(prec->val);
 	}
 
+	if ( prec->tpro >= 2 )
+		printf( "%s: Process %s, val %f\n",
+			epicsThreadGetNameSelf(), prec->name, prec->val );
+
 	/* check for alarms */
 	checkAlarms(prec);
 
diff --git a/src/std/rec/biRecord.c b/src/std/rec/biRecord.c
index 7afea3d..6c22116 100644
--- a/src/std/rec/biRecord.c
+++ b/src/std/rec/biRecord.c
@@ -142,6 +142,12 @@ static long process(struct dbCommon *pcommon)
 		prec->udf = FALSE;
 	}
 	else if(status==2) status=0;
+
+        if ( prec->tpro >= 2 )
+                printf( "%s: Process %s, val %s\n",
+                        epicsThreadGetNameSelf(), prec->name,
+                        ( prec->val ? prec->onam : prec->znam ) );
+
 	/* check for alarms */
 	checkAlarms(prec);
 	/* check event list */
diff --git a/src/std/rec/boRecord.c b/src/std/rec/boRecord.c
index 8f60a0b..214f82d 100644
--- a/src/std/rec/boRecord.c
+++ b/src/std/rec/boRecord.c
@@ -221,6 +221,11 @@ static long process(struct dbCommon *pcommon)
 		} else prec->rval = (epicsUInt32)prec->val;
 	}
 
+        if ( prec->tpro >= 2 )
+                printf( "%s: Process %s, val %s\n",
+                        epicsThreadGetNameSelf(), prec->name,
+                        ( prec->val ? prec->onam : prec->znam ) );
+
 	/* check for alarms */
 	checkAlarms(prec);
 
diff --git a/src/std/rec/calcRecord.c b/src/std/rec/calcRecord.c
index 12a58d1..a45e879 100644
--- a/src/std/rec/calcRecord.c
+++ b/src/std/rec/calcRecord.c
@@ -125,6 +125,11 @@ static long process(struct dbCommon *pcommon)
 
     timeLast = prec->time;
     recGblGetTimeStamp(prec);
+    
+    if ( prec->tpro >= 2 )
+        printf( "%s: Process %s, val %f\n",
+                epicsThreadGetNameSelf(), prec->name, prec->val );
+
     /* check for alarms */
     checkAlarms(prec, &timeLast);
     /* check event list */
diff --git a/src/std/rec/calcoutRecord.c b/src/std/rec/calcoutRecord.c
index 8b55255..80071b3 100644
--- a/src/std/rec/calcoutRecord.c
+++ b/src/std/rec/calcoutRecord.c
@@ -249,6 +249,11 @@ static long process(struct dbCommon *pcommon)
                 prec->udf = isnan(prec->val);
             }
         }
+
+        if ( prec->tpro >= 2 )
+                printf( "%s: Process %s, val %f\n",
+                        epicsThreadGetNameSelf(), prec->name, prec->val );
+
         checkAlarms(prec);
         /* check for output link execution */
         switch (prec->oopt) {
diff --git a/src/std/rec/longinRecord.c b/src/std/rec/longinRecord.c
index bd3c24a..40e2242 100644
--- a/src/std/rec/longinRecord.c
+++ b/src/std/rec/longinRecord.c
@@ -152,6 +152,10 @@ static long process(struct dbCommon *pcommon)
 	recGblGetTimeStamp(prec);
 	if (status==0) prec->udf = FALSE;
 
+        if ( prec->tpro >= 2 )
+                printf( "%s: Process %s, val %d\n",
+                        epicsThreadGetNameSelf(), prec->name, prec->val );
+
 	/* check for alarms */
 	checkAlarms(prec, &timeLast);
 	/* check event list */
diff --git a/src/std/rec/longoutRecord.c b/src/std/rec/longoutRecord.c
index 6062ad7..0fba405 100644
--- a/src/std/rec/longoutRecord.c
+++ b/src/std/rec/longoutRecord.c
@@ -154,6 +154,10 @@ static long process(struct dbCommon *pcommon)
 		if (!status) convert(prec,value);
 	}
 
+        if ( prec->tpro >= 2 )
+                printf( "%s: Process %s, val %d\n",
+                        epicsThreadGetNameSelf(), prec->name, prec->val );
+
 	/* check for alarms */
 	checkAlarms(prec);
 
diff --git a/src/std/rec/mbbiRecord.c b/src/std/rec/mbbiRecord.c
index ad5a8ce..96d54ab 100644
--- a/src/std/rec/mbbiRecord.c
+++ b/src/std/rec/mbbiRecord.c
@@ -201,6 +201,10 @@ static long process(struct dbCommon *pcommon)
     else if (status == 2)
         status = 0;
 
+    if ( prec->tpro >= 2 )
+        printf( "%s: Process %s, val %u\n",
+            epicsThreadGetNameSelf(), prec->name, prec->val );
+
     checkAlarms(prec, &timeLast);
     monitor(prec);
 
diff --git a/src/std/rec/mbboRecord.c b/src/std/rec/mbboRecord.c
index 0ae6a81..d99374a 100644
--- a/src/std/rec/mbboRecord.c
+++ b/src/std/rec/mbboRecord.c
@@ -224,6 +224,11 @@ static long process(struct dbCommon *pcommon)
     }
 
 CONTINUE:
+
+    if ( prec->tpro >= 2 )
+        printf( "%s: Process %s, val %u\n",
+            epicsThreadGetNameSelf(), prec->name, prec->val );
+
     /* Check for alarms */
     checkAlarms(prec);