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

Use debug logging for internal connection details #1803

Merged
merged 1 commit into from
Sep 4, 2024

Conversation

alxhill
Copy link
Contributor

@alxhill alxhill commented Sep 3, 2024

Summary

Currently, connection TTL & queue strategy are logged at INFO level for every request. This can result in a lot of noise in logs:

Screenshot 2024-09-03 at 11 00 56 AM

This PR switches them to DEBUG log levels.

Checklist

Delete items not relevant to your PR:

  • A human-readable description of the changes was provided to include in CHANGELOG

@CLAassistant
Copy link

CLAassistant commented Sep 3, 2024

CLA assistant check
All committers have signed the CLA.

@alxhill alxhill changed the title Use debug logging for internal connection details [client-v2] Use debug logging for internal connection details Sep 3, 2024
@alxhill alxhill changed the title [client-v2] Use debug logging for internal connection details Use debug logging for internal connection details Sep 3, 2024
@chernser
Copy link
Contributor

chernser commented Sep 3, 2024

Good day, @alxhill !
Thank you for reporting!
There may be another problem. Would you please share your settings?

It was expected that:

  • ApacheHttpClientConnection is reused many times (do you create a new client each request)
  • 0 ms setting seems not optimal because internal apache client connection will not be reused.

@alxhill
Copy link
Contributor Author

alxhill commented Sep 3, 2024

I think the TTL being set to zero should mean unlimited TTL:

CONNECTION_TTL("connection_ttl", 0L,
"Connection time to live in milliseconds. 0 or negative number means no limit."),
;

Our code did used to re-use connections a lot but doesn't as much any more. It's possible testcontainers is the primary culprit - I made a minimal repro that creates a Client and runs the test query and it shows this log-line a ton before it starts executing the tests:

@Testcontainers
class DemoTestContainersTest {

    @Container
    private final ClickHouseContainer clickHouseContainer = new ClickHouseContainer(ClickHouseConstants.IMAGE);

    private Client client;

    @BeforeEach
    void before() {
        client = new Client.Builder()
                .addEndpoint(
                        Protocol.HTTP, clickHouseContainer.getHost(), clickHouseContainer.getFirstMappedPort(), false)
                .setUsername(clickHouseContainer.getUsername())
                .setPassword(clickHouseContainer.getPassword())
                .compressServerResponse(true)
                .setSocketTimeout(30, ChronoUnit.SECONDS)
                .build();
    }

    @Test
    void connected() throws Exception {
        System.out.println("starting test query");
        try (QueryResponse response =
                client.query(clickHouseContainer.getTestQueryString()).join()) {
            System.out.println("response: " + response);
        }
        System.out.println("finished test query");
    }
}

Output logs here: ch-connection.log

@chernser
Copy link
Contributor

chernser commented Sep 3, 2024

@alxhill thank you for the test!

You seems using old version of the client-v2 (internally it uses old one but now has a new implementation).
Latest version is 0.6.5 - it will utilize connection reuse.
Also you may switch to the new implementation byte setting com.clickhouse.client.api.Client.Builder#useNewImplementation (method is deprecated because soon it will be only one internal implementation)

@alxhill
Copy link
Contributor Author

alxhill commented Sep 4, 2024

Those logs are using the 0.6.5 jar fwiw. Our codebase is mostly client v2, but there's a few uses of client v1 floating around that will be producing excess logs too. As a sidenote, I did enable the useNewImplementation flag but it's causing some breaks - for example date_time_input_format='best_effort' doesn't successfully convert timestamps that were previously being parsed. Is GitHub issues a good place to report these?

Separate from fixing up our code, would still encourage switching this logline to DEBUG as it doesn't seem important enough to show up as INFO for all consumers

@chernser
Copy link
Contributor

chernser commented Sep 4, 2024

@alxhill
I see now - there is a lot records because client is called from multiple threads.
Please create an issue with all feature you would like to see asap in client-v2 (list them all in one issue - I will split if needed).

@chernser chernser merged commit 0a7b9de into ClickHouse:main Sep 4, 2024
54 of 59 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants