You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by GitBox <gi...@apache.org> on 2021/01/15 20:16:41 UTC
[GitHub] [kafka] vvcephei opened a new pull request #9911: MINOR: Fix StreamsOptimizedTest
vvcephei opened a new pull request #9911:
URL: https://github.com/apache/kafka/pull/9911
We have seen recent system test timeouts associated with this test.
Analysis revealed an excessive amount of time spent searching
for test conditions in the logs.
This change addresses the issue by dropping some unnecessary
checks and using a more efficient log search mechanism.
### Committer Checklist (excluded from commit message)
- [ ] Verify design and implementation
- [ ] Verify test coverage and CI build status
- [ ] Verify documentation (including upgrade notes)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-761176712
In detail, here's my analysis of a recent timeout:
Looking at the debug log for the test, there seem to be some remote commands that really burn the clock. Consider this segment:
```
680 [DEBUG - 2021-01-12 21:34:54,612 - remoteaccount - _log - lineno:160]: ubuntu@worker8: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
681 [INFO - 2021-01-12 21:35:18,751 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
682 [DEBUG - 2021-01-12 21:35:19,752 - remoteaccount - _log - lineno:160]: ubuntu@worker8: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
683 [INFO - 2021-01-12 21:36:08,111 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
684 [DEBUG - 2021-01-12 21:36:09,112 - remoteaccount - _log - lineno:160]: ubuntu@worker8: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
685 [INFO - 2021-01-12 21:37:38,270 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
686 [DEBUG - 2021-01-12 21:37:39,271 - remoteaccount - _log - lineno:160]: ubuntu@worker8: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
687 [INFO - 2021-01-12 21:40:28,719 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
688 [DEBUG - 2021-01-12 21:40:29,720 - remoteaccount - _log - lineno:160]: ubuntu@worker8: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
689 [INFO - 2021-01-12 21:46:12,541 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
```
The first sed takes 20 seconds, the second takes 50, the third takes 90, the fourth takes 2.5 minutes, and the last takes 5.5 minutes.
The next time we try it (on worker6) it pushes the whole test over the 30m mark:
```
1030 [DEBUG - 2021-01-12 21:46:29,527 - remoteaccount - _log - lineno:160]: ubuntu@worker6: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
1031 [INFO - 2021-01-12 21:53:31,673 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
1032 [DEBUG - 2021-01-12 21:53:32,675 - remoteaccount - _log - lineno:160]: ubuntu@worker6: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
1033 [INFO - 2021-01-12 22:01:38,267 - streams_optimized_test - all_source_subtopology_tasks - lineno:134]: Returned [] from assigned task check
1034 [DEBUG - 2021-01-12 22:01:39,268 - remoteaccount - _log - lineno:160]: ubuntu@worker6: Running ssh command: sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/^A/p' /mnt/streams/streams.log
1035 [INFO - 2021-01-12 22:03:50,579 - runner_client - log - lineno:240]: RunnerClient: kafkatest.tests.streams.streams_optimized_test.StreamsOptimizedTest.test_upgrade_optimized_topology: FAIL:
1036 Traceback (most recent call last):
1037 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/ducktape-0.8.0-py3.6.egg/ducktape/tests/runner_client.py", line 134, in run
1038 data = self.run_test()
1039 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/ducktape-0.8.0-py3.6.egg/ducktape/tests/runner_client.py", line 192, in run_test
1040 return self.test_context.function(self.test)
1041 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/tests/kafkatest/tests/streams/streams_optimized_test.py", line 88, in test_upgrade_optimized_topology
1042 self.verify_processing(processors, verify_individual_operations=True)
1043 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/tests/kafkatest/tests/streams/streams_optimized_test.py", line 114, in verify_processing
1044 if not self.all_source_subtopology_tasks(processor):
1045 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/tests/kafkatest/tests/streams/streams_optimized_test.py", line 133, in all_source_subtopology_tasks
1046 found = list(processor.node.account.ssh_capture("sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/\1/p' %s" % processor.LOG_FILE, allow_fail=True))
1047 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/ducktape-0.8.0-py3.6.egg/ducktape/cluster/remoteaccount.py", line 651, in next
1048 return next(self.iter_obj)
1049 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/ducktape-0.8.0-py3.6.egg/ducktape/cluster/remoteaccount.py", line 318, in output_generator
1050 for line in iter(stdout.readline, ''):
1051 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/paramiko-2.7.2-py3.6.egg/paramiko/file.py", line 291, in readline
1052 new_data = self._read(n)
1053 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/paramiko-2.7.2-py3.6.egg/paramiko/channel.py", line 1361, in _read
1054 return self.channel.recv(size)
1055 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/paramiko-2.7.2-py3.6.egg/paramiko/channel.py", line 699, in recv
1056 out = self.in_buffer.read(nbytes, self.timeout)
1057 File "/home/jenkins/workspace/system-test-kafka-branch-builder/kafka/venv/lib/python3.6/site-packages/paramiko-2.7.2-py3.6.egg/paramiko/buffered_pipe.py", line 160, in read
1058 self._cv.wait(timeout)
1059 File "/usr/local/lib/python3.6/threading.py", line 295, in wait
1060 waiter.acquire()
1061 KeyboardInterrupt
```
Looks like the first sed is 7 minutes, the second 8 minutes, and then we time out in the third.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-761183334
Hey @bbejeck , I don't suppose you have time for a review of this, since you had come context?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] guozhangwang commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
guozhangwang commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-763000056
Re-triggered unit tests again, some other flaky tests are supposed to be fixed last night.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-763133788
Thanks, all! I'll go ahead and merge despite the build, since only a Python file has changed.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on a change in pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on a change in pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#discussion_r558572032
##########
File path: tests/kafkatest/tests/streams/streams_optimized_test.py
##########
@@ -65,30 +66,41 @@ def test_upgrade_optimized_topology(self):
processors = [processor1, processor2, processor3]
- # produce records continually during the test
+ self.logger.info("produce records continually during the test")
Review comment:
Switched comments to logs so that I could tell what phase of the test we were in while reading the logs.
##########
File path: tests/kafkatest/tests/streams/streams_optimized_test.py
##########
@@ -65,30 +66,41 @@ def test_upgrade_optimized_topology(self):
processors = [processor1, processor2, processor3]
- # produce records continually during the test
+ self.logger.info("produce records continually during the test")
self.producer.start()
- # start all processors unoptimized
+ self.logger.info("start all processors unoptimized")
for processor in processors:
self.set_topics(processor)
processor.CLEAN_NODE_ENABLED = False
self.verify_running_repartition_topic_count(processor, 4)
+ self.logger.info("verify unoptimized")
self.verify_processing(processors, verify_individual_operations=False)
+ self.logger.info("stop unoptimized")
stop_processors(processors, self.stopped_message)
+ self.logger.info("reset")
self.reset_application()
+ for processor in processors:
+ processor.node.account.ssh("mv " + processor.LOG_FILE + " " + processor.LOG_FILE + ".1", allow_fail=False)
+ processor.node.account.ssh("mv " + processor.STDOUT_FILE + " " + processor.STDOUT_FILE + ".1", allow_fail=False)
+ processor.node.account.ssh("mv " + processor.STDERR_FILE + " " + processor.STDERR_FILE + ".1", allow_fail=False)
+ processor.node.account.ssh("mv " + processor.CONFIG_FILE + " " + processor.CONFIG_FILE + ".1", allow_fail=False)
Review comment:
resetting all these files helps debugging, because you can easily see what happened before vs. after the reset. It also simplifies our verification logic, making it easy to search for processing that took place after the reset.
##########
File path: tests/kafkatest/tests/streams/streams_optimized_test.py
##########
@@ -110,34 +122,25 @@ def verify_running_repartition_topic_count(processor, repartition_topic_count):
% repartition_topic_count + str(processor.node.account))
def verify_processing(self, processors, verify_individual_operations):
+ # This test previously had logic to account for skewed assignments, in which not all processors may
+ # receive active assignments. I don't think this will happen anymore, but keep an eye out if we see
+ # test failures here. If that does resurface, note that the prior implementation was not correct.
+ # A better approach would be to make sure we see processing of each partition across the whole cluster
+ # instead of just expecting to see each node perform some processing.
for processor in processors:
- if not self.all_source_subtopology_tasks(processor):
- if verify_individual_operations:
- for operation in self.operation_pattern.split('\|'):
- self.do_verify(processor, operation)
- else:
- self.do_verify(processor, self.operation_pattern)
+ if verify_individual_operations:
+ for operation in self.operation_pattern.split('\|'):
+ self.do_verify(processor, operation)
else:
- self.logger.info("Skipping processor %s with all source tasks" % processor.node.account)
+ self.do_verify(processor, self.operation_pattern)
def do_verify(self, processor, pattern):
self.logger.info("Verifying %s processing pattern in STDOUT_FILE" % pattern)
- with processor.node.account.monitor_log(processor.STDOUT_FILE) as monitor:
- monitor.wait_until(pattern,
- timeout_sec=60,
- err_msg="Never saw processing of %s " % pattern + str(processor.node.account))
-
- def all_source_subtopology_tasks(self, processor):
- retries = 0
- while retries < 5:
- found = list(processor.node.account.ssh_capture("sed -n 's/.*current active tasks: \[\(\(0_[0-9], \)\{3\}0_[0-9]\)\].*/\1/p' %s" % processor.LOG_FILE, allow_fail=True))
Review comment:
Sadly, this message never appeared in any of the logs. I guess the log format has changed. What that meant for the test was that it was just excluding every node from the verification!
The comment at L125 contains my suggestions for how to perform this check in a more reliable fashion, but I actually don't think we need it anymore at all.
##########
File path: tests/kafkatest/tests/streams/streams_optimized_test.py
##########
@@ -110,34 +122,25 @@ def verify_running_repartition_topic_count(processor, repartition_topic_count):
% repartition_topic_count + str(processor.node.account))
def verify_processing(self, processors, verify_individual_operations):
+ # This test previously had logic to account for skewed assignments, in which not all processors may
+ # receive active assignments. I don't think this will happen anymore, but keep an eye out if we see
+ # test failures here. If that does resurface, note that the prior implementation was not correct.
+ # A better approach would be to make sure we see processing of each partition across the whole cluster
+ # instead of just expecting to see each node perform some processing.
Review comment:
This comment explains the following diff.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei merged pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei merged pull request #9911:
URL: https://github.com/apache/kafka/pull/9911
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-761180464
I confirmed this change works both positively and negatively:
```
================================================================================
SESSION REPORT (ALL TESTS)
ducktape version: 0.8.0
session_id: 2021-01-15--012
run time: 2 minutes 0.269 seconds
tests run: 1
passed: 1
failed: 0
ignored: 0
================================================================================
test_id: kafkatest.tests.streams.streams_optimized_test.StreamsOptimizedTest.test_upgrade_optimized_topology
status: PASS
run time: 2 minutes 0.208 seconds
--------------------------------------------------------------------------------
```
For the negative test, I changed the regex string in the test and confirmed that the test fails by timeout waiting to see that (wrong) string in the stdout.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [kafka] vvcephei commented on pull request #9911: MINOR: Fix StreamsOptimizedTest
Posted by GitBox <gi...@apache.org>.
vvcephei commented on pull request #9911:
URL: https://github.com/apache/kafka/pull/9911#issuecomment-763190069
Cherry-picked to 2.7 and 2.6
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org