The behavior you described could be explained by the following.
As indicated in my original answer InfluxMeterRegistry under the hood uses StepCounters to implement counters.
To obtain the actual count StepCounter uses the following code:
@Override
public double count() {
return value.poll();
}
where value turns out to be a convenient implementation for handling double values of the StepValue class.
Please, be aware that when describing poll, they indicate:
/**
* @return The value for the last completed interval.
*/
public V poll() {
rollCount(clock.wallTime());
return previous;
}
i.e. it is reporting the value for the last completed interval, not the actual one.
Consider review this test, reproduced here for completeness, I think it describes the programmed behavior in a very clear way:
@Test
void poll() {
final AtomicLong aLong = new AtomicLong(42);
final long stepTime = 60;
final StepValue<Long> stepValue = new StepValue<Long>(clock, stepTime) {
@Override
public Supplier<Long> valueSupplier() {
return () -> aLong.getAndSet(0);
}
@Override
public Long noValue() {
return 0L;
}
};
assertThat(stepValue.poll()).isEqualTo(0L);
clock.add(Duration.ofMillis(1));
assertThat(stepValue.poll()).isEqualTo(0L);
clock.add(Duration.ofMillis(59));
assertThat(stepValue.poll()).isEqualTo(42L);
clock.add(Duration.ofMillis(60));
assertThat(stepValue.poll()).isEqualTo(0L);
clock.add(Duration.ofMillis(60));
assertThat(stepValue.poll()).isEqualTo(0L);
aLong.set(24);
assertThat(stepValue.poll()).isEqualTo(0L);
clock.add(Duration.ofMillis(60));
assertThat(stepValue.poll()).isEqualTo(24L);
clock.add(Duration.ofMillis(stepTime / 2));
aLong.set(27);
assertThat(stepValue.poll()).isEqualTo(24L);
stepValue._closingRollover();
assertThat(stepValue.poll()).isEqualTo(27L);
}
Note that for this purpose increment is doing something "equivalent" to the different aLong.set presented in the previous test code.
I think this other test could be of help as well for describing how the value reported is the one for the last completed interval, not the actual one:
@Test
void count() {
Counter counter = registry.counter("my.counter");
assertThat(counter).isInstanceOf(StepCounter.class);
assertThat(counter.count()).isEqualTo(0);
counter.increment();
clock.add(config.step());
assertThat(counter.count()).isEqualTo(1);
counter.increment();
counter.increment(5);
clock.add(config.step());
assertThat(counter.count()).isEqualTo(6);
clock.add(config.step());
assertThat(counter.count()).isEqualTo(0);
}
In conclusion, what I tried meaning is that the log in your code fragment:
Metrics.counter("registration.upsigned").increment();
LOG.info("Size of registration-counter now: " + Metrics.counter("registration.upsigned").count());
will always print out the value for the last completed interval, not for the current one, and it may be or not the value you expect depending on whether or not the interval in which you performed the increment elapsed.
That is not specific for InfluxDB but for any Metrics registry implementation based on the step concept.
In any case, the most valuable information you can obtain is the one that is actually published to your backend, InfluxDB or the one you defined - which causes among other things the step related values to be polled.
I don't know if it will shed some additional light or not, but you can read about this rate data aggregation step based mechanism in the Micrometer documentation when they describe client side rate aggregation - please, note that InfluxBD is one of this client-side rate aggregation monitoring system. From the docs:
Micrometer efficiently maintains rate data by means of a step value
that accumulates data for the current publishing interval. When the
step value is polled (when publishing, for example), if the step
value detects that the current interval has elapsed, it moves
current data to “previous” state. This previous state is what is
reported until the next time current data overwrites it. The
following image shows the interaction of current and previous
state, along with polling:
* From my understanding the arrows signal publish events.
As indicated, your log (which, as you can see in the source code presented above, polls when performing count) will always report the previous value presented in the image which may or not be the same you expect according to your increments invocations and step intervals (your log may behave as the first pollAsRate presented in the image, in which it will print out 0 despite the fact two increments were performed).
If you prefer, here is a simplified version of the process, more focused in your example:
Please, take in mind that a step based counter:
- Always maintains two values under the hood, the current one, internal, not visible outside the class, and a previous one, visible, the one that is taking into account when publishing data.
- Every step is configured with a time interval for rate aggregation.
- The previous value is updated with the current value when any of two things happen:
- A poll is requested, either by invoking
count manually or usually when publishing information to your metrics registry, and the step interval is elapsed.
- Micrometer shutdowns and claims for a closing rollover, i.e., send the last acquired data to your metrics repository.
To illustrate it, please, consider the following test case, I think it could be of help:
import java.time.Duration;
import org.junit.jupiter.api.Test;
import io.micrometer.core.instrument.Clock;
import io.micrometer.core.instrument.Counter;
import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Tags;
import io.micrometer.core.instrument.simple.CountingMode;
import io.micrometer.core.instrument.simple.SimpleConfig;
import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
public class MicrometerTest {
@Test
public void testStepCounterBehavior() {
Clock clock = Clock.SYSTEM;
MeterRegistry registry = new SimpleMeterRegistry(new SimpleConfig() {
@Override
public String get(String key) {
return null;
}
@Override
public CountingMode mode() {
return CountingMode.STEP;
}
@Override
public Duration step() {
return Duration.ofMillis(1000);
}
}, clock);
double value = -1, previousValue = -1;
Tags tags = Tags.empty();
Counter counter = registry.counter("test.counter", tags);
long start = clock.wallTime();
counter.increment();
int i = 0;
while (clock.wallTime() < start + 5000) {
value = counter.count();
if (value != previousValue) {
System.out.printf("Current value: %.0f. Elapsed (millis): %d.\n", value, clock.wallTime() - start);
previousValue = value;
if (i++ == 2) {
counter.increment(3);
}
}
}
}
}
It will output, with some random bias, something similar to:
Current value: 0. Elapsed (millis): 0.
Current value: 1. Elapsed (millis): 601.
Current value: 0. Elapsed (millis): 1600.
Current value: 3. Elapsed (millis): 2600.
Current value: 0. Elapsed (millis): 3600.
Note that except for the first spurious output which reports a time less than the configured 1 second step interval, I think motivated by the different initialization stuff, the values and time printed are consistent with the explanation provided.
