Open fovea1959 opened 1 year ago
The extra overhead (if any) only shows up when doing tracing, which is NOT the usual use case. The optimizations that are there keep the usual no tracing case as quick as possible. On a Raspberry Pi 0, the optimizations are not nanoseconds....
On Tuesday, July 4, 2023 at 03:28:45 PM EDT, E. A. (Ed) Graham, Jr. ***@***.***> wrote:
@EAGrahamJr commented on this pull request.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -353,6 +356,12 @@ private Ads1x15(int controller, Model model, Address address, PgaConfig pgaConfi boardPinInfo = new Ads1x15BoardPinInfo(model, pgaConfig.getVoltage()); device = I2CDevice.builder(address.getValue()).setController(controller).setByteOrder(ByteOrder.BIG_ENDIAN) .build(); +
- Logger.trace("{}", () -> {
If you don't mind, a few comments..
Your use of functional indirection for logging has a couple of things that I think are a little odd:
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -464,20 +473,48 @@ private void setDataRate(int dataRate, byte dataRateMask) { this.dataRateMask = dataRateMask; }
This is one of the optimizations that just doesn't need to be done - the call to get the current time in millis is negligible in the overall call pattern.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
- Logger.trace("waitUntilReady hit");
- t0 = System.currentTimeMillis();
- }
- SleepUtil.sleepMillis(dataRateSleepMillis);
- int incrementalSleepMillis = Math.max(dataRateSleepMillis / 20, 1);
- int i = 0;
- while (true) {
- short data = device.readShort(ADDR_POINTER_CONFIG);
- if ((data & 0x8000) != 0) break;
- SleepUtil.sleepMillis(incrementalSleepMillis);
- i++;
- }
- if (amTracing) {
Another example of nanosecond operations that should just be in-lined.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -486,18 +523,16 @@ protected void setConfig(int adcNumber) { byte config_lsb = (byte) (dataRateMask | comparatorMode.getMask() | comparatorPolarity.getMask() | (latchingComparator ? CONFIG_LSB_COMP_LATCHING : 0) | comparatorQueue.getMask()); device.writeI2CBlockData(ADDR_POINTER_CONFIG, config_msb, config_lsb);
- Logger.trace("msb: 0x{}, lsb: 0x{}", Integer.toHexString(config_msb & 0xff),
- Integer.toHexString(config_lsb & 0xff));
- Logger.trace("setConfig: 0x{} 0x{}", () -> Integer.toHexString(config_msb & 0xff),
Use of "setConfig" isn't necessary - the log format should output the class and method (see the tinylog.properties resource file).
— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.Message ID: @.***>
that being said, I'll do whatever needs to be done to get the fixes integrated....
On Thursday, July 6, 2023 at 09:05:16 PM EDT, Doug Wegscheid ***@***.***> wrote:
The extra overhead (if any) only shows up when doing tracing, which is NOT the usual use case. The optimizations that are there keep the usual no tracing case as quick as possible. On a Raspberry Pi 0, the optimizations are not nanoseconds....
On Tuesday, July 4, 2023 at 03:28:45 PM EDT, E. A. (Ed) Graham, Jr. ***@***.***> wrote:
@EAGrahamJr commented on this pull request.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -353,6 +356,12 @@ private Ads1x15(int controller, Model model, Address address, PgaConfig pgaConfi boardPinInfo = new Ads1x15BoardPinInfo(model, pgaConfig.getVoltage()); device = I2CDevice.builder(address.getValue()).setController(controller).setByteOrder(ByteOrder.BIG_ENDIAN) .build(); +
- Logger.trace("{}", () -> {
If you don't mind, a few comments..
Your use of functional indirection for logging has a couple of things that I think are a little odd:
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -464,20 +473,48 @@ private void setDataRate(int dataRate, byte dataRateMask) { this.dataRateMask = dataRateMask; }
This is one of the optimizations that just doesn't need to be done - the call to get the current time in millis is negligible in the overall call pattern.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
- Logger.trace("waitUntilReady hit");
- t0 = System.currentTimeMillis();
- }
- SleepUtil.sleepMillis(dataRateSleepMillis);
- int incrementalSleepMillis = Math.max(dataRateSleepMillis / 20, 1);
- int i = 0;
- while (true) {
- short data = device.readShort(ADDR_POINTER_CONFIG);
- if ((data & 0x8000) != 0) break;
- SleepUtil.sleepMillis(incrementalSleepMillis);
- i++;
- }
- if (amTracing) {
Another example of nanosecond operations that should just be in-lined.
In diozero-core/src/main/java/com/diozero/devices/Ads1x15.java:
@@ -486,18 +523,16 @@ protected void setConfig(int adcNumber) { byte config_lsb = (byte) (dataRateMask | comparatorMode.getMask() | comparatorPolarity.getMask() | (latchingComparator ? CONFIG_LSB_COMP_LATCHING : 0) | comparatorQueue.getMask()); device.writeI2CBlockData(ADDR_POINTER_CONFIG, config_msb, config_lsb);
- Logger.trace("msb: 0x{}, lsb: 0x{}", Integer.toHexString(config_msb & 0xff),
- Integer.toHexString(config_lsb & 0xff));
- Logger.trace("setConfig: 0x{} 0x{}", () -> Integer.toHexString(config_msb & 0xff),
Use of "setConfig" isn't necessary - the log format should output the class and method (see the tinylog.properties resource file).
— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.Message ID: @.***>
Taking a look - the amTracing instance variable is a little unusual.
Taking a look - the amTracing instance variable is a little unusual.
That's kind of common practice to ensure that specific instructions are not run when a method is invoked. In this case, I believe the intent was to avoid any overhead when logging calls are made - e.g. when the trace
method is called with method invocations in the parameter list, the parameters are evaluated prior to method invocation. So
Logger.trace("msb: 0x{}, lsb: 0x{}", Integer.toHexString(config_msb & 0xff),
Integer.toHexString(config_lsb & 0xff));
always calls both toHexString
methods, whether tracing is enabled or not. If you put the if (amTracing)
in front of that, nothing gets evaluated except the if
.
On the other hand, the PR changes also tries to get around calling "un-necessary" functions through the use of functional interfaces.
Logger.trace("setConfig: 0x{} 0x{}", () -> Integer.toHexString(config_msb & 0xff),
() -> Integer.toHexString(config_lsb & 0xff));
But there's even more overhead because
trace
is called (because parameters are evaluated first)Item 3 is the actual "gotcha" that a lot of people just really don't know about.
But there's even more overhead because
1. creates an anonymous class for _each_ defined block
yep, you are correct. Not sure this is a runtime issue.
2. creates an instance of said class (so there's 2 classes and 2 instances above)
yep, you are correct. But the class will only be loaded once from the classpath, which is expensive compared to running the constructor.
If I had instantiated the Suppliers ONCE and then passed the instantiated objects to the logging calls, that would avoid the "multiple instantiations of the (already loaded) classes" issue that you have called out here. The calls I guarded/avoided with the lambdas are probably not expensive enough to be worth it. So, I removed the lambdas.
3. invokes the function each time `trace` is called (because parameters are evaluated **first**)
just so we all know, however, I'm pretty sure I'm on solid ground on this one. tinylog does not invoke the lazy parameter Supplier<> functions unless the logging is actually taking place. I confirmed this in the source code, and via experimentation (test case pasted below). Deferring the execution of the Supplier<> functions until they are needed is precisely why the tinylog (and log4j2) designers put those signatures in there, but given points 1 and 2 above, using the lambdas is probably appropriate for more expensive operations than the ones we are talking about here.
TinylogTest.java:
public class TinylogTest {
public static void main(String[] args) {
new TinylogTest().go();
}
boolean expensiveOperationExecuted = false;
void go() {
expensiveOperationExecuted = false;
org.tinylog.Logger.info("Info: {}", () -> expensiveOperation());
System.out.println ("expensive operation was invoked by .info() = " + expensiveOperationExecuted);
expensiveOperationExecuted = false;
org.tinylog.Logger.debug("Debug: {}", () -> expensiveOperation());
System.out.println ("expensive operation was invoked by .debug() = " + expensiveOperationExecuted);
}
String expensiveOperation() {
expensiveOperationExecuted = true;
return "Hi, Bob!";
}
}
log4j2.xml:
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="WARN">
<Appenders>
<Console name="console" target="SYSTEM_OUT" follow="false">
</Console>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="console"/>
</Root>
</Loggers>
</Configuration>
build.gradle:
plugins {
id 'java'
}
group 'org.example'
version '1.0-SNAPSHOT'
repositories {
mavenCentral()
}
dependencies {
implementation 'org.tinylog:tinylog-jboss:2.5.0'
implementation 'org.apache.logging.log4j:log4j-core:2.20.0'
testImplementation 'org.junit.jupiter:junit-jupiter-api:5.7.2'
testRuntimeOnly 'org.junit.jupiter:junit-jupiter-engine:5.7.2'
}
test {
useJUnitPlatform()
}
Program output:
> Task :TinylogTest.main()
Info: Hi, Bob!
expensive operation was invoked by .info() = true
expensive operation was invoked by .debug() = false
just so we all know, however, I'm pretty sure I'm on solid ground on this one. tinylog does not invoke the lazy parameter Supplier<> functions unless the logging is actually taking place.
TIL - I didn't know TinyLog took a list of parameter suppliers - yes, you are correct. (I was expecting Object...
rather than Supplier<Object>...
- guess I should have checked :grinning: )
Fixing two ads1x15 issues:
1) just waiting for an amount of time is not always sufficient. Changed code to wait for the conversion complete bit.
2) range mapping for ads1015 was not correct.