Request delay reaches minute level after enabling SASL/PLAIN

[cobolbaby]

Env:

• cp-kafka version: 5.5.2

Test Case

root@broker1:/# cat /kafka/consumer-sasl.properties
enable.auto.commit=false
security.protocol=SASL_PLAINTEXT
sasl.mechanism=PLAIN
sasl.jaas.config=org.apache.kafka.common.security.plain.PlainLoginModule required \
  username="???" \
  password="???";
root@broker1:/# time kafka-console-consumer --bootstrap-server localhost:9093 --property print.key=true --property print.timestamp=true --topic infra-minio-f6-aoi-notify --from-beginning --max-messages 1 --consumer.config /kafka/consumer-sasl.properties --timeout-ms 120000

LogAppendTime:1641866605124 pics/SMT/AOI FOV/S20B/LF2824222A02S2/20211118/20211118083657-GF1BPPA0HL.JPG {"EventName":"s3:ObjectRemoved:Delete","Key":"pics/SMT/AOI FOV/S20B/LF2824222A02S2/20211118/20211118083657-GF1BPPA0HL.JPG","Records":[{"eventVersion":"2.0","eventSource":"minio:s3","awsRegion":"","eventTime":"2022-01-11T02:03:13.333Z","eventName":"s3:ObjectRemoved:Delete","userIdentity":{"principalId":"line"},"requestParameters":{"principalId":"line","region":"","sourceIPAddress":"192.168.16.42"},"responseElements":{"content-length":"44416","x-amz-request-id":"16C914F61DA210C8","x-minio-deployment-id":"efe9247b-005d-4407-a042-7b95430e00ce","x-minio-origin-endpoint":"https://f6-te-aoi-oss.ipt.inventec.net"},"s3":{"s3SchemaVersion":"1.0","configurationId":"Config","bucket":{"name":"pics","ownerIdentity":{"principalId":"line"},"arn":"arn:aws:s3:::pics"},"object":{"key":"SMT%2FAOI+FOV%2FS20B%2FLF2824222A02S2%2F20211118%2F20211118083657-GF1BPPA0HL.JPG","sequencer":"16C914F7B837491A"}},"source":{"host":"192.168.16.42","port":"","userAgent":"MinIO (linux; amd64) minio-go/v7.0.20 oss-archive/minio-tool"}}]}
Processed a total of 1 messages

real    1m25.094s
user    0m15.595s
sys 0m8.360s
root@broker1:/# 
root@broker1:/#
root@broker1:/# 
root@broker1:/# time kafka-console-consumer --bootstrap-server localhost:19092 --property print.key=true --property print.timestamp=true --topic infra-minio-f6-aoi-notify --from-beginning --max-messages 1 --timeout-ms 120000
LogAppendTime:1641866605124 pics/SMT/AOI FOV/S20B/LF2824222A02S2/20211118/20211118083657-GF1BPPA0HL.JPG {"EventName":"s3:ObjectRemoved:Delete","Key":"pics/SMT/AOI FOV/S20B/LF2824222A02S2/20211118/20211118083657-GF1BPPA0HL.JPG","Records":[{"eventVersion":"2.0","eventSource":"minio:s3","awsRegion":"","eventTime":"2022-01-11T02:03:13.333Z","eventName":"s3:ObjectRemoved:Delete","userIdentity":{"principalId":"line"},"requestParameters":{"principalId":"line","region":"","sourceIPAddress":"192.168.16.42"},"responseElements":{"content-length":"44416","x-amz-request-id":"16C914F61DA210C8","x-minio-deployment-id":"efe9247b-005d-4407-a042-7b95430e00ce","x-minio-origin-endpoint":"https://f6-te-aoi-oss.ipt.inventec.net"},"s3":{"s3SchemaVersion":"1.0","configurationId":"Config","bucket":{"name":"pics","ownerIdentity":{"principalId":"line"},"arn":"arn:aws:s3:::pics"},"object":{"key":"SMT%2FAOI+FOV%2FS20B%2FLF2824222A02S2%2F20211118%2F20211118083657-GF1BPPA0HL.JPG","sequencer":"16C914F7B837491A"}},"source":{"host":"192.168.16.42","port":"","userAgent":"MinIO (linux; amd64) minio-go/v7.0.20 oss-archive/minio-tool"}}]}
Processed a total of 1 messages

real    0m5.097s
user    0m3.613s
sys 0m0.505s

[cobolbaby]

It seems that the time of commit offset will exceed the default timeout configuration. How much impact will the authentication operation have on performance?

[cobolbaby]

Problems caused by host dns.

[notizklotz]

I observed the same problem and I could resolve it by advertising the brokers using fully qualified domain names.

If the brokers are avertised by IP adresses this causes a reverse DNS lookup via java.net.InetAddress#getHostName() which is slow on some environments. The relevant code is here: https://github.com/apache/kafka/blob/3.3.1/clients/src/main/java/org/apache/kafka/common/network/SaslChannelBuilder.java#L231