[
https://issues.apache.org/jira/browse/SOLR-3157?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13217250#comment-13217250
]
Yonik Seeley edited comment on SOLR-3157 at 2/27/12 4:21 PM:
-------------------------------------------------------------
Here's a patch that changes the log format for tests to something that should
be easier to debug tests with multiple core containers.
Example:
{code}
18808 T=64 C3 UPDATE /update
{waitSearcher=true&wt=javabin&wt=javabin&commit_end_point=true&commit=true&version=2&version=2}
{commit=} 0 60
18809 T=61 C2 UPDATE /update
{waitSearcher=true&wt=javabin&commit=true&version=2} {commit=} 0 94
18810 T=1 oascc.ZkStateReader.updateCloudState Manual update of cluster state
initiated
18811 T=1 oascc.ZkStateReader.updateCloudState Updating cloud state from
ZooKeeper...
18855 T=99 C1 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=190
status=0 QTime=35
18864 T=100 C3 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=189
status=0 QTime=1
18868 T=101 C2 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=180
status=0 QTime=1
{code}
- first number is milliseconds since the start of the test. Makes it easy to
sort by the first number or subtract to get elapsed time, and is more relevant
to a short running test.
- T=101 is the thread ID... this will be useful for any multi-threaded test.
- C2 is the core number. we don't use core name since there can be multiple
core containers with the same name (like "") in these distributed tests.
- package names just use the first letters catenated together for brevity
- aliases for common log output are implemented (REQ and UPDATE)
- I got rid of the double logging for updates
- single line format is easier to read and easier to grep and do things with
scripts
- the first time a core is seen (or whenever it's cloudstate changes) that is
output. This allows correlation of C2 with URLs.
For example, if we want to know about core C2, we search back in the logs for
C2_STATE and see
{code}
ASYNC NEW_CORE C2 name= org.apache.solr.core.SolrCore@22e38fca
url=http://127.0.0.1:58141/solr/ node=127.0.0.1:58141_solr
C2_STATE=coll:collection1 core: props:{num_shards=3, shard=shard3,
state=active, core=, collection=collection1, node_name=127.0.0.1:58141_solr,
base_url=http://127.0.0.1:58141/solr}
{code}
We can only currently do core / container correlation when SolrRequestInfo is
set (i.e. request handler requests). I tried setting a ThreadGroup for the
jetty instances we spin up, but they didn't stick (request threads were still
part of the main thread group). Still, I think this is moving in the right
direction.
was (Author: [email protected]):
Here's a patch that changes the log format for tests to something that
should be easier to debug tests with multiple core containers.
Example:
{code}
18808 T=64 C3 UPDATE /update
{waitSearcher=true&wt=javabin&wt=javabin&commit_end_point=true&commit=true&version=2&version=2}
{commit=} 0 60
18809 T=61 C2 UPDATE /update
{waitSearcher=true&wt=javabin&commit=true&version=2} {commit=} 0 94
18810 T=1 oascc.ZkStateReader.updateCloudState Manual update of cluster state
initiated
18811 T=1 oascc.ZkStateReader.updateCloudState Updating cloud state from
ZooKeeper...
18855 T=99 C1 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=190
status=0 QTime=35
18864 T=100 C3 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=189
status=0 QTime=1
18868 T=101 C2 REQ /select {distrib=false&wt=javabin&q=*:*&version=2} hits=180
status=0 QTime=1
{code}
- first number is milliseconds since the start of the test. Makes it easy to
sort by the first number or subtract to get elapsed time, and is more relevant
to a short running test.
- T=101 is the thread ID... this will be useful for any multi-threaded test.
- C2 is the core number. we don't use core name since there can be multiple
core containers with the same name (like "") in these distributed tests.
- package names just use the first letters catenated together for brevity
- aliases for common log output are implemented (REQ and UPDATE)
- I got rid of the double logging for updates
- the first time a core is seen (or whenever it's cloudstate changes) that is
output. This allows correlation of C2 with URLs.
For example, if we want to know about core C2, we search back in the logs for
C2_STATE and see
{code}
ASYNC NEW_CORE C2 name= org.apache.solr.core.SolrCore@22e38fca
url=http://127.0.0.1:58141/solr/ node=127.0.0.1:58141_solr
C2_STATE=coll:collection1 core: props:{num_shards=3, shard=shard3,
state=active, core=, collection=collection1, node_name=127.0.0.1:58141_solr,
base_url=http://127.0.0.1:58141/solr}
{code}
We can only currently do core / container correlation when SolrRequestInfo is
set (i.e. request handler requests). I tried setting a ThreadGroup for the
jetty instances we spin up, but they didn't stick (request threads were still
part of the main thread group). Still, I think this is moving in the right
direction.
> custom logging
> --------------
>
> Key: SOLR-3157
> URL: https://issues.apache.org/jira/browse/SOLR-3157
> Project: Solr
> Issue Type: Test
> Reporter: Yonik Seeley
> Priority: Blocker
> Attachments: SOLR-3157.patch
>
>
> We need custom logging to decipher tests with multiple core containers,
> cores, in a single JVM.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
