getting started ... but why does vert.x throw exceptions?

[Olaf Eichstädt]

I would greatly appreciate your insights and suggestions about why I drive vert.x into exceptions:

I have started to run a simple setup with 3 dockerized subsystems (1 instance each):

• zookeeper:3.6.1
• kafka:2.12-2.5.0
• confluentinc/ksqldb-server:latest

I use Python producers and subscribers and kafka (and hence zookeeper) seems to work fine, i.e. respond as expected to published and subscribed topics.

I then tried some first steps towards stream processing (inspired by Tim Berglund's talk at Devoxx Poland 2018 (https://www.youtube.com/watch?v=LM-aQQQes4Q&t=2024s). 

But ksqlDB (I believe he version is 0.11.) and/or the CLI seems to freeze on me:

I start the CLI in another container:
docker run -it confluentinc/ksqldb-cli ksql http://<IP_OF_MY_SERVER_IN_THE_LAN>:8088  

ksql> LIST TOPICS;

 Kafka Topic | Partitions | Partition Replicas 

-----------------------------------------------

 json        | 1          | 1                  

-----------------------------------------------

ksql> CREATE STREAM JSON_RAW (key_1 varchar, key_2 varchar) WITH (value_format='JSON', kafka_topic='json');

 Message        

----------------

 Stream created 

----------------

ksql> SET 'auto.offset.reset'='earliest';

Successfully changed local property 'auto.offset.reset' to 'earliest'. Use the UNSET command to revert your change.

ksql>LIST STREAMS;

 Stream Name | Kafka Topic | Format 

------------------------------------

 JSON_RAW    | json        | JSON   

------------------------------------

Everything looks good so far ... there is some tangible delay between committing the command and getting the feedback, but at least there is feedback. 

ksql> SELECT * FROM JSON_RAW EMIT CHANGES;

Press CTRL-C to interrupt

Before I see any output related to data, I get exceptions and error dumps starting like this:

Sep 29, 2020 11:17:29 AM io.vertx.core.impl.BlockedThreadChecker

WARNING: Thread Thread[vert.x-eventloop-thread-1,5,main]=Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 2835 ms, time limit is 2000 ms

Sep 29, 2020 11:17:41 AM io.vertx.core.impl.BlockedThreadChecker

WARNING: Thread Thread[vert.x-eventloop-thread-1,5,main]=Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 9408 ms, time limit is 2000 ms

io.vertx.core.VertxException: Thread blocked

    at java...@11.0.5/sun.reflect.generics.reflectiveObjects.ParameterizedTypeImpl.getRawType(ParameterizedTypeImpl.java:41)

    at app//com.fasterxml.jackson.databind.type.TypeFactory._fromParamType(TypeFactory.java:1451)

[...]

The values of the topic/stream are then buried in the many lines of traceback ...

Any suggestions on how to debug this one? 

[Sergio Pena Anaya]

Hey Olaf,

I usually get similar warning messages when doing remote debugging on the server. When I set a break-point and stay there more than 2s (which is pretty common), I start seeing those warnings in the server console. You mentioned you're getting a delay in your client/server responses, so probably something in the server is causing the slowness which takes > 2s to process, thus causing the warning messages.

But it seems you're seeing them in the CLI that you cannot even see the topic output? I didn't understand that part, cause the warnings should've been on the server side, and the topic output is in the CLI.

Either way. I did a quick look at the code and there's no max. time for that thread defined; so it is using the default max. time which 2s. You won't get rid of these warnings. Only thing is to find the bad performance issue on the server. Probably connection slowness between ksql and kafka?

- Sergio

--
You received this message because you are subscribed to the Google Groups "ksqldb-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ksql-users+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/ksql-users/d421d519-5fb6-486c-8acb-1483e8a45fd9n%40googlegroups.com.

[Olaf Eichstädt]

@Sergio: thanks for the feedback. 

I am not debugging anything, so this is not the cause of the hold up.

So I am wondering why communication should be slow. When I am publishing and subscribing to Kafka (running on the server) from my development machine, messages seems to travel pretty swiftly from the producer on the machine to kafka on the server and back to the subscriber on the machine. So my guess would be that the ksqlDB-server is not happy for some reason.

The server is pretty small, but the CPU load (7%) seems to be fine. RAM is at around  70%%, respectively) seem to be within limits. Admittedly, RAM is not abundant on this machine, but the container running ksqlDB says it is running with 100-150MB memory and even if that suddenly increased by some 50, 100MB it should still be ok ... 

I just tried it again ... the error traces appear on STOUT an hence the terminal. They also appear in the log that Docker provides. But after having restarted the ksqlDB container just now, things seem to be a little better than previously: after the (long) error traces comes the output you would expect from the query. First it lists all values starting from earliest (almost, see below). When I then publish new values, I see them being appended to the output i the terminal. Yesterday, the output was sprinkled in between the exceptions'  error traces. 

When I publish new values today, they now appear pretty quickly appended to the output in the terminal.

I also now notice just now that the KSQL query does not show the first 2 values of the topic which were produced with kafkacat. When I look at the topic with a Python consumer, I can see that the value string contains an "\r" after the {}. And the values from the Python producer do not. And apparently I also inserted a weird message that has no json at all ... I will need to try this again with a clean stream of mesages ...

[Tim Fox]

Hi Olaf, can you please post the full stack trace, this will help in diagnosing the issue.

[Olaf Eichstädt]

Hello Tim,

yes, I can do that (when I am back in the office), I still have the original log, please stand by ...

I also have to say that is becomes more and more difficult to reproduce the issues (i.e. it starts to work as expected now) ... very strange. Or related to some weird artefact that only happens when the system is brand new.

I also noticed that I used a mix of messages produced from (1) a Python producer and (2) kafkacat ... where kafka produced messages with a timestamp of "-1" ... that might be part of the issue.

The fact that ksqlDB slowly seems to work as expected is somewhat disconcerting, bu talso encouraging so that I will do some more experiments to see if I can reproduce the original issue with the blocked thread. 

[Olaf Eichstädt]

Here is the logfile that I retrieved from my docker host (I have removed some typing errors and escape sequences from cursor movements). For some reason the log reads from bottom to top. I also realized that the log starts with a session where it does not show the initial creation of the JSON_RAW stream ... sorry about that.

Please note that around 2020-09-29 10:47, there is a dump of the underlying topic including the 2 initial messages produced with kafkacat (rowtime: N/A) and some bad message <<key: {\"key_1\":\"value_1-4\",\"key_2\":\"value_2-4\"}, value: some key>> where key and value got switched by accident when publishing the message from the Python producer.

2020-09-29 10:53 shows how the Stream "JSON RAW" was created and what happened after <<SELECT * FROM JSON_RAW EMIT CHANGES LIMIT 1;>>.

I hope the log helps to understand what happened. If you would like me to try anything else, please let me know. 

[Tim Fox]

Hi Olaf,

The stack trace shows that the Jackson deserialization of the results returned from the server (StreamedRow) is taking some time to execute. I can see it's trying to load a class, so I'm going to guess you only see this the first time you execute the query?

I don't think there is anything to worry about here. This is on the client so I think it would be fine for us to configure the Vert.x blocked thread check interval to a higher value (e.g. 10 seconds)

[Olaf Eichstädt]

I am way out of my depth here ... looking at the stack trace makes me dizzy. That you were able to identify the Jackson deserializer as the root cause is a miracle to me ;-)

Indeed it seems that the problem goes away over time ... but why would it take such a long time to load/initialize the Jackson deserializer? Where does it come from? Was it installed together with the ksqlDB-CLI or does it "lazily" arrive from a remote resource? 

[Tim Fox]

ksqlDB uses a custom Jackson deserializer (LogicalSchemaDeserializer) which is included in the binary. The deserialization is dynamic so classes will be loaded in order to instantiate objects if they're not already loaded. Loading a class is a reasonably slow operation and often involves disk IO. It could be that your machine is slow/overloaded?

It should also be noted that the warning is fired when the _total`- event loop execute time exceeds a threshold, so it could be something else in the handling of the response was slow and it just so happened to be captured on the call to loadClass. It might be worth us doing a JMH benchmark of the deserialization code in case there is a real performance problem there. 

--
You received this message because you are subscribed to the Google Groups "ksqldb-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ksql-users+...@googlegroups.com.

To view this discussion on the web, visit https://groups.google.com/d/msgid/ksql-users/be5194e3-3c73-4b5d-bc9e-d3239c00cc71n%40googlegroups.com.