[
https://issues.apache.org/jira/browse/IGNITE-23451?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17889744#comment-17889744
]
Aleksandr Chesnokov edited comment on IGNITE-23451 at 10/17/24 1:02 PM:
------------------------------------------------------------------------
The reason of problem is that one of listeners expects expression
{code:java}
"default2 - size before/after: (\\S+)/\\1"{code}
But output for CLI handler is
{noformat}
Defragmentation is completed for cache groups:
default3 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
default1 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
default2 - size before/after: 44MB/44.02MB, time took: 0 mins 12 secs
{noformat}
And 44MB and 44.02MB are not equals. It looks like the size increased after
defragmentation.
Moreover, it depends on CommandHandler. If we run with JmxCommandHandler,
everything is ok and output is
{noformat}
default2 - size before/after: 44.02MB/44.02MB {noformat}
And the problem appears if we run CliCommandHandler.
If we add delay before starting defragmentation for JMX handler, there also
will be same problem
{noformat}
default2 - size before/after: 44MB/44.02MB, time took: 0 mins 12 secs {noformat}
was (Author: JIRAUSER307233):
The reason of problem is that one of listeners expects expression
{code:java}
"default2 - size before/after: (\\S+)/\\1"{code}
But output is
{noformat}
Defragmentation is completed for cache groups:
default3 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
default1 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
default2 - size before/after: 44MB/44.02MB, time took: 0 mins 12 secs
{noformat}
44MB and 44.02MB are not equals. It looks like the size increased after
defragmentation.
Moreover, it depends on CommandHandler. If we run with JmxCommandHandler,
everything is ok and output is
{noformat}
default2 - size before/after: 44.02MB/44.02MB {noformat}
And the problem appears if we run CliCommandHandler
> Flakiness in testDefragmentationStatus
> --------------------------------------
>
> Key: IGNITE-23451
> URL: https://issues.apache.org/jira/browse/IGNITE-23451
> Project: Ignite
> Issue Type: Bug
> Reporter: Aleksandr Chesnokov
> Assignee: Aleksandr Chesnokov
> Priority: Minor
> Labels: test
>
> GridCommandHandlerDefragmentationTest.testDefragmentationStatus is flaky
> {noformat}
> ======= Failed test run #1 ==========
> ------- Stdout: -------
> java.lang.AssertionError
> at org.junit.Assert.fail(Assert.java:86)
> at org.junit.Assert.assertTrue(Assert.java:41)
> at org.junit.Assert.assertTrue(Assert.java:52)
> at
> org.apache.ignite.testframework.junits.JUnitAssertAware.assertTrue(JUnitAssertAware.java:35)
> at
> org.apache.ignite.util.GridCommandHandlerDefragmentationTest.testDefragmentationStatus(GridCommandHandlerDefragmentationTest.java:450)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.apache.ignite.testframework.junits.GridAbstractTest$6.run(GridAbstractTest.java:2499)
> at java.base/java.lang.Thread.run(Thread.java:829)
> ======= Failed test run #2 ==========
> java.lang.AssertionError
> at org.junit.Assert.fail(Assert.java:86)
> at org.junit.Assert.assertTrue(Assert.java:41)
> at org.junit.Assert.assertTrue(Assert.java:52)
> at
> org.apache.ignite.testframework.junits.JUnitAssertAware.assertTrue(JUnitAssertAware.java:35)
> at
> org.apache.ignite.util.GridCommandHandlerDefragmentationTest.testDefragmentationStatus(GridCommandHandlerDefragmentationTest.java:450)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.apache.ignite.testframework.junits.GridAbstractTest$6.run(GridAbstractTest.java:2499)
> at java.base/java.lang.Thread.run(Thread.java:829)
> ------- Stdout: -------
> [12:56:58] >>> Starting test:
> GridCommandHandlerDefragmentationTest#testDefragmentationStatus[cmdHnd=cli]
> <<<
> [12:56:58] >>> Heap: 632 MB used / 2048 MB commited / 2048 MB max <<<
> [12:56:58] >>> Non-Heap: 170 MB used / 180 MB commited / 0 MB max <<<
> [12:56:58] __________ ________________
> [12:56:58] / _/ ___/ |/ / _/_ __/ __/
> [12:56:58] _/ // (7 7 // / / / / _/
> [12:56:58] /___/\___/_/|_/___/ /_/ /x___/
> [12:56:58]
> [12:56:58] ver. 2.17.0-SNAPSHOT#20241015-sha1:DEV
> [12:56:58] 2024 Copyright(C) Apache Software Foundation
> [12:56:58]
> [12:56:58] Ignite documentation: https://ignite.apache.org
> [12:56:58]
> [12:56:58] Quiet mode.
> [12:56:58] ^-- Logging by 'GridTestLog4jLogger [quiet=true, config=null]'
> [12:56:58] ^-- To see **FULL** console log here add -DIGNITE_QUIET=false
> or "-v" to ignite.{sh|bat}
> [12:56:58]
> [12:56:58] OS: Linux 5.4.0-163-generic amd64
> [12:56:58] VM information: OpenJDK Runtime Environment 11.0.20.1+1 Eclipse
> Adoptium OpenJDK 64-Bit Server VM 11.0.20.1+1
> [12:56:58] Configured plugins:
> [12:56:58] ^-- StanByClusterTestProvider 1.0
> [12:56:58] ^-- null
> [12:56:58]
> [12:56:58] ^-- PageMemory tracker plugin 1.0
> [12:56:58] ^-- null
> [12:56:58]
> [12:56:58] ^-- TestDistibutedConfigurationPlugin 1.0
> [12:56:58] ^-- null
> [12:56:58]
> [12:56:58] ^-- NodeValidationPluginProvider 1.0
> [12:56:58] ^-- null
> [12:56:58]
> [12:56:58] Configured failure handler: [hnd=NoOpFailureHandler
> [super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet
> [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]]]
> [12:56:58] Message queue limit is set to 0 which may lead to potential
> OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due
> to message queues growth on sender and receiver sides.
> [12:56:58] Encryption keys loaded from metastore. [grps=,
> masterKeyName=null]
> [12:56:58] Data Regions Started: 4
> [12:56:58]
> [12:56:58] ^-- sysMemPlc region [type=internal, persistence=true,
> lazyAlloc=false,
> [12:56:58] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=100MB, allocTotal=0MB]
> [12:56:58] ^-- default region [type=default, persistence=true,
> lazyAlloc=true,
> [12:56:58] ... initCfg=50MB, maxCfg=50MB, usedRam=0MB, freeRam=100%,
> allocRam=0MB, allocTotal=0MB]
> [12:56:58] ^-- metastoreMemPlc region [type=internal,
> persistence=true, lazyAlloc=false,
> [12:56:58] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=100MB, allocTotal=0MB]
> [12:56:58] ^-- volatileDsMemPlc region [type=user, persistence=false,
> lazyAlloc=true,
> [12:56:58] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=0MB]
> [12:56:58] Security status [authentication=off, sandbox=off, tls/ssl=off]
> [12:56:58]
> [12:56:58] Ignite node started OK (id=0430df1c, instance
> name=gridCommandHandlerTest0)
> [12:56:58] >>> Ignite cluster is in INACTIVE state (limited functionality
> available). Use control.(sh|bat) script or
> IgniteCluster.state(ClusterState.ACTIVE) to change the state.
> [12:56:58] Topology snapshot [ver=1, locNode=0430df1c, servers=1,
> clients=0, state=INACTIVE, CPUs=8, offheap=0.1GB, heap=2.0GB]
> Control utility [ver. 2.17.0-SNAPSHOT#20241015-sha1:DEV]
> 2024 Copyright(C) Apache Software Foundation
> User: teamcity
> Time: 2024-10-15T12:57:00.018
> Command [DEFRAGMENTATION] started
> Arguments: --defragmentation schedule --nodes gridCommandHandlerTest0 --yes
>
> --------------------------------------------------------------------------------
> gridCommandHandlerTest0:
> success=true
> msg=Scheduling completed successfully.
> Command [DEFRAGMENTATION] finished with code: 0
> Control utility has completed execution at: 2024-10-15T12:57:00.036
> Execution time: 17 ms
> [12:57:00] Ignite node stopped OK [name=gridCommandHandlerTest0,
> uptime=00:00:01.876]
> [12:57:00] __________ ________________
> [12:57:00] / _/ ___/ |/ / _/_ __/ __/
> [12:57:00] _/ // (7 7 // / / / / _/
> [12:57:00] /___/\___/_/|_/___/ /_/ /x___/
> [12:57:00]
> [12:57:00] ver. 2.17.0-SNAPSHOT#20241015-sha1:DEV
> [12:57:00] 2024 Copyright(C) Apache Software Foundation
> [12:57:00]
> [12:57:00] Ignite documentation: https://ignite.apache.org
> [12:57:00]
> [12:57:00] Quiet mode.
> [12:57:00] ^-- Logging by 'GridTestLog4jLogger [quiet=true, config=null]'
> [12:57:00] ^-- To see **FULL** console log here add -DIGNITE_QUIET=false
> or "-v" to ignite.{sh|bat}
> [12:57:00]
> [12:57:00] OS: Linux 5.4.0-163-generic amd64
> [12:57:00] VM information: OpenJDK Runtime Environment 11.0.20.1+1 Eclipse
> Adoptium OpenJDK 64-Bit Server VM 11.0.20.1+1
> [12:57:00] Configured plugins:
> [12:57:00] ^-- StanByClusterTestProvider 1.0
> [12:57:00] ^-- null
> [12:57:00]
> [12:57:00] ^-- PageMemory tracker plugin 1.0
> [12:57:00] ^-- null
> [12:57:00]
> [12:57:00] ^-- TestDistibutedConfigurationPlugin 1.0
> [12:57:00] ^-- null
> [12:57:00]
> [12:57:00] ^-- NodeValidationPluginProvider 1.0
> [12:57:00] ^-- null
> [12:57:00]
> [12:57:00] Configured failure handler: [hnd=NoOpFailureHandler
> [super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet
> [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]]]
> [12:57:00] Message queue limit is set to 0 which may lead to potential
> OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due
> to message queues growth on sender and receiver sides.
> [12:57:00] Encryption keys loaded from metastore. [grps=,
> masterKeyName=null]
> [12:57:00] Data Regions Started: 6
> [12:57:00]
> [12:57:00] ^-- defragPartitionsDataRegion region [type=user,
> persistence=true, lazyAlloc=false,
> [12:57:00] ... initCfg=27MB, maxCfg=27MB, usedRam=0MB, freeRam=100%,
> allocRam=27MB, allocTotal=0MB]
> [12:57:00] ^-- sysMemPlc region [type=internal, persistence=true,
> lazyAlloc=false,
> [12:57:00] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=100MB, allocTotal=0MB]
> [12:57:00] ^-- default region [type=default, persistence=true,
> lazyAlloc=true,
> [12:57:00] ... initCfg=20MB, maxCfg=20MB, usedRam=0MB, freeRam=100%,
> allocRam=0MB, allocTotal=0MB]
> [12:57:00] ^-- metastoreMemPlc region [type=internal,
> persistence=true, lazyAlloc=false,
> [12:57:00] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=100MB, allocTotal=0MB]
> [12:57:00] ^-- defragMappingDataRegion region [type=user,
> persistence=true, lazyAlloc=false,
> [12:57:00] ... initCfg=3MB, maxCfg=3MB, usedRam=0MB, freeRam=100%,
> allocRam=8MB, allocTotal=0MB]
> [12:57:00] ^-- volatileDsMemPlc region [type=user, persistence=false,
> lazyAlloc=true,
> [12:57:00] ... initCfg=40MB, maxCfg=100MB, usedRam=0MB,
> freeRam=100%, allocRam=0MB]
> [12:57:00] Security status [authentication=off, sandbox=off, tls/ssl=off]
> [12:57:00]
> [12:57:00] Ignite node started OK (id=ceb39469, instance
> name=gridCommandHandlerTest0)
> [12:57:00] >>> Ignite cluster is in INACTIVE state (limited functionality
> available). Use control.(sh|bat) script or
> IgniteCluster.state(ClusterState.ACTIVE) to change the state.
> [12:57:00] Topology snapshot [ver=1, locNode=ceb39469, servers=1,
> clients=0, state=INACTIVE, CPUs=-1, offheap=0.1GB, heap=0.1GB]
> [12:57:00] ^-- Baseline [id=0, size=1, online=1, offline=0]
> Control utility [ver. 2.17.0-SNAPSHOT#20241015-sha1:DEV]
> 2024 Copyright(C) Apache Software Foundation
> User: teamcity
> Time: 2024-10-15T12:57:00.726
> Command [DEFRAGMENTATION] started
> Arguments: --port 11211 --defragmentation status --yes
>
> --------------------------------------------------------------------------------
> Defragmentation is completed for cache groups:
> default1 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
> Defragmentation is in progress for cache groups:
> default2 - partitions processed/all: 127/1024, time elapsed: 0 mins 0
> secs
> Awaiting defragmentation: default3
> Command [DEFRAGMENTATION] finished with code: 0
> Control utility has completed execution at: 2024-10-15T12:57:00.766
> Execution time: 39 ms
> Control utility [ver. 2.17.0-SNAPSHOT#20241015-sha1:DEV]
> 2024 Copyright(C) Apache Software Foundation
> User: teamcity
> Time: 2024-10-15T12:57:03.538
> Command [DEFRAGMENTATION] started
> Arguments: --port 11211 --defragmentation status --yes
>
> --------------------------------------------------------------------------------
> Defragmentation is completed for cache groups:
> default3 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
> default1 - size before/after: 0MB/0MB, time took: 0 mins 0 secs
> default2 - size before/after: 44MB/44.02MB, time took: 0 mins 3 secs
> Command [DEFRAGMENTATION] finished with code: 0
> Control utility has completed execution at: 2024-10-15T12:57:03.556
> Execution time: 17 ms
> [12:57:03] >>> Stopping test:
> GridCommandHandlerDefragmentationTest#testDefragmentationStatus[cmdHnd=cli]
> in 5447 ms <<<
> [12:57:03] >>> Heap: 995 MB used / 2048 MB commited / 2048 MB max <<<
> [12:57:03] >>> Non-Heap: 173 MB used / 184 MB commited / 0 MB max <<<
> [12:57:03] Ignite node stopped OK [name=gridCommandHandlerTest0,
> uptime=00:00:02.926]
> ------- Stderr: -------
> [2024-10-15T12:56:58,116][WARN
> ][test-runner-#10666%gridCommandHandlerTest%][G] Ignite work directory is not
> provided, automatically resolved to: /data/tcAgent/work/7bc1c54bc719b67c/work
> [2024-10-15T12:56:58,119][WARN
> ][test-runner-#10666%gridCommandHandlerTest%][IgniteKernal%gridCommandHandlerTest0]
> Peer class loading is enabled (disable it in production for performance and
> deployment consistency reasons)
> [2024-10-15T12:56:58,126][WARN
> ][test-runner-#10666%gridCommandHandlerTest%][TestRecordingCommunicationSpi]
> Message queue limit is set to 0 which may lead to potential OOMEs when
> running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message
> queues growth on sender and receiver sides.
> [2024-10-15T12:56:58,137][WARN
> ][test-runner-#10666%gridCommandHandlerTest%][GridCacheDatabaseSharedManager]
> DataRegion maxSize=52.4 MB is smaller than defaultInitialSize=268.4 MB,
> setting initialSize to 52.4 MB
> [2024-10-15T12:56:58,143][WARN
> ][test-runner-#10666%gridCommandHandlerTest%][IgniteH2Indexing] Custom H2
> serialization is already configured, will override.
> [2024-10-15T12:57:00,065][WARN ][async-runnable-runner-1][G] Ignite work
> directory is not provided, automatically resolved to:
> /data/tcAgent/work/7bc1c54bc719b67c/work
> [2024-10-15T12:57:00,068][WARN
> ][async-runnable-runner-1][IgniteKernal%gridCommandHandlerTest0] Peer class
> loading is enabled (disable it in production for performance and deployment
> consistency reasons)
> [2024-10-15T12:57:00,077][WARN
> ][async-runnable-runner-1][TestRecordingCommunicationSpi] Message queue limit
> is set to 0 which may lead to potential OOMEs when running cache operations
> in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender
> and receiver sides.
> [2024-10-15T12:57:00,093][WARN
> ][async-runnable-runner-1][GridCacheDatabaseSharedManager] Region
> [defragMappingDataRegion] size 3.1 MB is too small for concurrency level=8.
> Automatically increasing it to 8.4 MB
> [2024-10-15T12:57:00,097][WARN ][async-runnable-runner-1][IgniteH2Indexing]
> Custom H2 serialization is already configured, will override.
> [2024-10-15T12:57:00,230][WARN
> ][sys-#10810%gridCommandHandlerTest0%][PageMemoryImpl] Page replacements
> started, pages will be rotated with disk, this will affect storage
> performance (consider increasing DataRegionConfiguration#setMaxSize for data
> region): default
> [2024-10-15T12:57:01,181][WARN
> ][defragmentation-worker-#10830%gridCommandHandlerTest0%][PageMemoryImpl]
> Page replacements started, pages will be rotated with disk, this will affect
> storage performance (consider increasing DataRegionConfiguration#setMaxSize
> for data region): defragMappingDataRegion
> [2024-10-15T12:57:01,214][WARN
> ][defragmentation-worker-#10832%gridCommandHandlerTest0%][PageMemoryImpl]
> Page replacements started, pages will be rotated with disk, this will affect
> storage performance (consider increasing DataRegionConfiguration#setMaxSize
> for data region): defragPartitionsDataRegion
> [2024-10-15T12:57:03,557][ERROR][main][] Test failed
> [test=GridCommandHandlerDefragmentationTest#testDefragmentationStatus[cmdHnd=cli],
> duration=5444]
> java.lang.AssertionError: null
> at org.junit.Assert.fail(Assert.java:86) ~[junit-4.12.jar:4.12]
> at org.junit.Assert.assertTrue(Assert.java:41) ~[junit-4.12.jar:4.12]
> at org.junit.Assert.assertTrue(Assert.java:52) ~[junit-4.12.jar:4.12]
> at
> org.apache.ignite.testframework.junits.JUnitAssertAware.assertTrue(JUnitAssertAware.java:35)
> ~[ignite-core-2.17.0-SNAPSHOT-tests.jar:2.17.0-SNAPSHOT]
> at
> org.apache.ignite.util.GridCommandHandlerDefragmentationTest.testDefragmentationStatus(GridCommandHandlerDefragmentationTest.java:450)
> ~[test-classes/:?]
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method) ~[?:?]
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> ~[?:?]
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> ~[?:?]
> at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> ~[junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> ~[junit-4.12.jar:4.12]
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> ~[junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> ~[junit-4.12.jar:4.12]
> at
> org.apache.ignite.testframework.junits.GridAbstractTest$6.run(GridAbstractTest.java:2499)
> ~[ignite-core-2.17.0-SNAPSHOT-tests.jar:2.17.0-SNAPSHOT]
> at java.base/java.lang.Thread.run(Thread.java:829) ~[?:?]
> {noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
