Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NioInboundPipeline frames read metrics are always zero #15479

Closed
emre-aydin opened this issue Aug 22, 2019 · 4 comments

Comments

@emre-aydin
Copy link
Contributor

commented Aug 22, 2019

NioInboundPipeline#normalFramesRead and NioInboundPipeline#priorityFramesRead are never incremented. As a result, these metrics are always zero. Tested version is 3.12.2.

Corresponding metrics in NioOutboundPipeline are incremented correctly.

@pveentjer

This comment has been minimized.

Copy link
Member

commented Aug 22, 2019

I have checked the flow and there is not a obvious thing wrong with the logic. So I need to have more detail. What can of connection was used? Client to member or member to member connection?

@emre-aydin

This comment has been minimized.

Copy link
Contributor Author

commented Aug 22, 2019

Its client to member connection. See the following reproducer.

Starting the member:

public static void main(String[] args) {
    System.setProperty("hazelcast.diagnostics.enabled", "true");
    System.setProperty("hazelcast.diagnostics.metric.level", "Info");
    System.setProperty("hazelcast.diagnostics.metrics.period.seconds", "5");
    Config config = new Config();
    config.getAdvancedNetworkConfig()
            .setEnabled(true)
            .setMemberEndpointConfig(new ServerSocketEndpointConfig().setPort(5701))
            .setClientEndpointConfig(new ServerSocketEndpointConfig().setPort(5710));
    HazelcastInstance instance = Hazelcast.newHazelcastInstance(config);
}

Starting the client:

public static void main(String[] args) {
    System.setProperty("hazelcast.diagnostics.enabled", "true");
    System.setProperty("hazelcast.diagnostics.metric.level", "Info");
    System.setProperty("hazelcast.diagnostics.metrics.period.seconds", "5");

    ClientConfig clientConfig = new ClientConfig();
    clientConfig.getNetworkConfig().addAddress("127.0.0.1:5710");
    HazelcastInstance client = HazelcastClient.newHazelcastClient(clientConfig);
    client.getMap("map-1").put(1, new long[1000]);
}

In the client diagnostic logs, I have the following (only the relevant parts for brevity):

22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.bytesRead=15525]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.completedMigrations=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.idleTimeMs=184]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.normalFramesRead=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.ownerId=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.priorityFramesRead=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.processCount=32]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.startedMigrations=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.bytesWritten=8844]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.completedMigrations=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.idleTimeMs=185]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.normalFramesWritten=30]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.ownerId=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.priorityFramesWritten=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.priorityWriteQueueSize=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.processCount=32]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.startedMigrations=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.writeQueueSize=0]

Note that bytesRead is greater than 0 but both normalFramesRead and priorityFramesRead are
0 whereas normalFramesRead should also be greater than 0. Note that normalFramesWritten is
greater than 0 as expected. You can find the lines of interest below:

22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.bytesRead=15525]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.normalFramesRead=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].in.priorityFramesRead=0]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.bytesWritten=8844]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.normalFramesWritten=30]
22-08-2019 10:31:20 1566459080908 Metric[tcp.connection[/127.0.0.1:58143->/127.0.0.1:5710].out.priorityFramesWritten=0]
@pveentjer

This comment has been minimized.

Copy link
Member

commented Aug 30, 2019

I ran with 4.0 and get the following metrics

30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.bytesRead=3978]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.completedMigrations=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.idleTimeMs=2982]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.normalFramesRead=11]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.ownerId=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.priorityFramesRead=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.processCount=11]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].in.startedMigrations=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.bytesWritten=8440]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.completedMigrations=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.idleTimeMs=2984]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.normalFramesWritten=9]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.ownerId=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.priorityFramesWritten=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.priorityWriteQueueSize=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.processCount=11]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.scheduled=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.startedMigrations=0]
30-08-2019 08:56:49 1567144609077 Metric[tcp.connection[/127.0.0.1:47301->/127.0.0.1:5710].out.writeQueueSize=0]

The appropriate metrics are provided. I'll check 3.12 next.

@pveentjer pveentjer added this to the 3.12.3 milestone Aug 30, 2019
@pveentjer pveentjer self-assigned this Aug 30, 2019
pveentjer added a commit to pveentjer/hazelcast that referenced this issue Aug 30, 2019
fix hazelcast#15479

no forward port is needed since the bug is resolved on 4.0
due to client protocol changes.
pveentjer added a commit to pveentjer/hazelcast that referenced this issue Sep 2, 2019
fix hazelcast#15479

no forward port is needed since the bug is resolved on 4.0
due to client protocol changes.
@mmedenjak

This comment has been minimized.

Copy link
Contributor

commented Sep 26, 2019

Closing as I assume this is fixed with #15479. @pveentjer @emre-aydin please reopen if you disagree.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.