Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Refresh LogstashBasicMarker implementation and remove synchronisation #617

Merged
merged 4 commits into from
Aug 24, 2021
Merged

Refresh LogstashBasicMarker implementation and remove synchronisation #617

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
8f0926a
Use a CopyOnWriteArrayList instead of Vector and remove synchronisation
brenuart Aug 20, 2021
a2e26eb
Remove useless synchronisation on LogstashMarker
brenuart Aug 20, 2021
e42b7e6
Additional tests to assert equals/hashCode takes references into account
brenuart Aug 20, 2021
1484243
Remove references from equals/hashCode and rely on the default behaviour
brenuart Aug 24, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
125 changes: 68 additions & 57 deletions src/main/java/net/logstash/logback/marker/LogstashBasicMarker.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,11 +18,11 @@
import java.util.Collections;
import java.util.Iterator;
import java.util.List;
import java.util.Vector;
import java.util.concurrent.CopyOnWriteArrayList;

import org.slf4j.Marker;

/* Copy of {@link org.slf4j.helpers.BasicMarker} from slf4j-api v1.7.12, with minor changes:
/* Copy of {@link org.slf4j.helpers.BasicMarker} from slf4j-api v1.7.31, with minor changes:
* 1. make the constructor public so that it can be extended in other packages
* 2. add getReferences() method

Expand Down Expand Up @@ -62,9 +62,13 @@
@SuppressWarnings("serial")
public class LogstashBasicMarker implements Marker {

private static final String OPEN = "[ ";
private static final String CLOSE = " ]";
private static final String SEP = ", ";

private final String name;
private List<Marker> refereceList;

private final List<Marker> referenceList = new CopyOnWriteArrayList<>();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I realize this is coming from slf4j-api's implementation, but this seems like a step in the wrong direction, since it will result in a lot of unused lists being allocated.

If markers and/or structured args are used heavily by an application, this will have an impact on memory usage and garbage collection.

The previous logic of deferring list creation until a reference is added seems better from a memory and garbage collection standpoint.

Having said that, I don't have exact numbers to back these claims up, so probably better to go with slf4j-api's implementation until proven otherwise.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with you... creating the list lazily would be better. However, this makes supporting concurrent accesses without synchronisation far less easier...

AFAIK people are not supposed to create many markers - hence the MarkerFactory caching previously created markers. Is it still true with Logstash?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LogstashBasicMarker is the superclass of all of the markers and structured argument implementations provided by logstash-logback-encoder. Caching is not used for any of these. So, for example, a marker (with an unused list) will be created every time this log line is executed.

logger.info("Foo {}", StructuredArguments.keyValue("bar", "baz"));

If that line is executed frequently, it'll create a lot of unused list garbage.

slf4j-api can cache the markers it creates, since those markers are simple string values, so they are easily cachable.

In any case, I understand the synchronization problems being addressed, so we can leave it as is. It's prioritizing performance over memory usage. Classic tradeoff.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understand the synchronization problems being addressed, so we can leave it as is. It's prioritizing performance over memory usage

But I'm also fighting against excessive memory allocations ;-)
The key point is whether LogstashBasicMarker must be thread-safe or not... IMHO, markers are not shared/mutated by multiple threads in most scenarios.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@philsttr I'm tempted to "drop" the thread-safe nature of the marker... certainly if we consider what has been said in #613 (comment)

Copy link
Collaborator Author

@brenuart brenuart Sep 6, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@philsttr Back on the referenceList again... The overhead of creating the COW list up-front is:

  • a zero-size object array
  • a ReentrantLock

Not much - but still too much if we consider that most LogstashMarkers won't have any children/references. BTW, what would be the use case? Can't we simply drop support for references and make the relevant methods "not implemented" ?

Alternatives:

(1) make it 'not thread-safe'. Start with a null reference list and lazy initialise it with a standard ArrayList when needed. Behaviour becomes unexpected if the Marker is accessed from multiple threads concurrently. Note that a COW list won't probably make multi-threaded usage more predictable: a first call to hasReferences() may return true but the list may be empty when you start iterating over it if another thread removed the elements in the meantime.

(2) keep it "thread-safe" but use an AtomicReference to hold the COW list. The overhead when no reference is ever added to the marker is limited to this atomic reference which is cheaper than the empty COW itself.

What's your opinion?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

BTW, what would be the use case? Can't we simply drop support for references and make the relevant methods "not implemented" ?

Unfortunately not, since the slf4j-api Logger methods only accept a single Marker argument. Support for multiple markers is implemented by having markers reference others.

Regarding thread-safety. I would rather keep it threadsafe. Another option (3).... similar to (2) but instead of using an AtomicReference, we could use a volatile field accessed via a static AtomicReferenceFieldUpdater. This prevents memory overhead of creating a lot of AtomicReference instances, at the expense of slightly slower access time and slightly more complex code.

/*
* BEGIN Modification in logstash-logback-encoder to make this constructor public
*/
Expand All @@ -78,77 +82,81 @@ public LogstashBasicMarker(String name) {
this.name = name;
}

/**
* {@inheritDoc}
*/
@Override
public String getName() {
return name;
}

public synchronized void add(Marker reference) {
/**
* {@inheritDoc}
*/
@Override
public void add(Marker reference) {
if (reference == null) {
throw new IllegalArgumentException(
"A null value cannot be added to a Marker as reference.");
throw new IllegalArgumentException("A null value cannot be added to a Marker as reference.");
}

// no point in adding the reference multiple times
if (this.contains(reference)) {
return;

} else if (reference.contains(this)) { // avoid recursion
// a potential reference should not its future "parent" as a reference
}
if (reference.contains(this)) { // avoid recursion, a potential reference should not hold its future "parent" as a reference
return;
} else {
// let's add the reference
if (refereceList == null) {
refereceList = new Vector<Marker>();
}
refereceList.add(reference);
}


referenceList.add(reference);
}

public synchronized boolean hasReferences() {
return ((refereceList != null) && (refereceList.size() > 0));
/**
* {@inheritDoc}
*/
@Override
public boolean hasReferences() {
return !referenceList.isEmpty();
}

/**
* {@inheritDoc}
*/
@Deprecated
@Override
public boolean hasChildren() {
return hasReferences();
}

public synchronized Iterator<Marker> iterator() {
if (refereceList != null) {
return refereceList.iterator();
} else {
return Collections.emptyIterator();
}
/**
* {@inheritDoc}
*/
@Override
public Iterator<Marker> iterator() {
return referenceList.iterator();
}

/*
* BEGIN Modification in logstash-logback-encoder to add this method
*/
protected List<Marker> getReferences() {
return refereceList == null
? Collections.emptyList()
: Collections.unmodifiableList(refereceList);
return Collections.unmodifiableList(referenceList);
}
/*
* END Modification in logstash-logback-encoder to add this method
*/

public synchronized boolean remove(Marker referenceToRemove) {
if (refereceList == null) {
return false;
}

int size = refereceList.size();
for (int i = 0; i < size; i++) {
Marker m = (Marker) refereceList.get(i);
if (referenceToRemove.equals(m)) {
refereceList.remove(i);
return true;
}
}
return false;
/**
* {@inheritDoc}
*/
@Override
public boolean remove(Marker referenceToRemove) {
return referenceList.remove(referenceToRemove);
}

/**
* {@inheritDoc}
*/
@Override
public boolean contains(Marker other) {
if (other == null) {
throw new IllegalArgumentException("Other cannot be null");
Expand All @@ -159,19 +167,20 @@ public boolean contains(Marker other) {
}

if (hasReferences()) {
for (int i = 0; i < refereceList.size(); i++) {
Marker ref = (Marker) refereceList.get(i);
for (Marker ref : referenceList) {
if (ref.contains(other)) {
return true;
}
}
}

return false;
}

/**
* This method is mainly used with Expression Evaluators.
* {@inheritDoc}
*/
@Override
public boolean contains(String name) {
if (name == null) {
throw new IllegalArgumentException("Other cannot be null");
Expand All @@ -182,21 +191,21 @@ public boolean contains(String name) {
}

if (hasReferences()) {
for (int i = 0; i < refereceList.size(); i++) {
Marker ref = (Marker) refereceList.get(i);
for (Marker ref : referenceList) {
if (ref.contains(name)) {
return true;
}
}
}

return false;
}

private static String OPEN = "[ ";
private static String CLOSE = " ]";
private static String SEP = ", ";


/**
* {@inheritDoc}
*/
@Override
public boolean equals(Object obj) {
if (this == obj) {
return true;
Expand All @@ -212,6 +221,10 @@ public boolean equals(Object obj) {
return name.equals(other.getName());
}

/**
* {@inheritDoc}
*/
@Override
public int hashCode() {
return name.hashCode();
}
Expand All @@ -220,13 +233,12 @@ public String toString() {
if (!this.hasReferences()) {
return this.getName();
}
StringBuilder sb = new StringBuilder(this.getName())
.append(' ')
.append(OPEN);
Iterator<Marker> it = this.iterator();
Marker reference;
StringBuffer sb = new StringBuffer(this.getName());
sb.append(' ').append(OPEN);
while (it.hasNext()) {
reference = (Marker) it.next();
sb.append(reference.getName());
sb.append(it.next().getName());
if (it.hasNext()) {
sb.append(SEP);
}
Expand All @@ -236,4 +248,3 @@ public String toString() {
return sb.toString();
}
}

36 changes: 5 additions & 31 deletions src/main/java/net/logstash/logback/marker/LogstashMarker.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,6 @@
package net.logstash.logback.marker;

import java.io.IOException;
import java.util.Objects;

import com.fasterxml.jackson.core.JsonGenerator;
import org.slf4j.Marker;
Expand Down Expand Up @@ -79,7 +78,7 @@ public <T extends LogstashMarker> T with(Marker reference) {
public abstract void writeTo(JsonGenerator generator) throws IOException;

@Override
public synchronized void add(Marker reference) {
public void add(Marker reference) {
if (reference instanceof EmptyLogstashMarker) {
for (Marker m : (EmptyLogstashMarker) reference) {
add(m);
Expand All @@ -89,31 +88,6 @@ public synchronized void add(Marker reference) {
}
}

@Override
public int hashCode() {
final int prime = 31;
int result = 1;
result = prime * result + super.hashCode();
result = prime * result + this.getReferences().hashCode();
return result;
}

@Override
public boolean equals(Object obj) {
if (this == obj) {
return true;
}
if (!super.equals(obj)) {
return false;
}
if (!(obj instanceof LogstashMarker)) {
return false;
}

LogstashMarker other = (LogstashMarker) obj;
return Objects.equals(this.getReferences(), other.getReferences());
}

/**
* Returns a String in the form of
* <pre>
Expand Down Expand Up @@ -142,8 +116,10 @@ public String toString() {
sb.append(", ");
}
String referenceToString = marker.toString();
sb.append(referenceToString);
appendSeparator = !referenceToString.isEmpty();
if (!referenceToString.isEmpty()) {
sb.append(referenceToString);
appendSeparator = true;
}
}

return sb.toString();
Expand All @@ -160,6 +136,4 @@ public String toString() {
protected String toStringSelf() {
return getName();
}


}
44 changes: 43 additions & 1 deletion src/test/java/net/logstash/logback/marker/MarkersTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@
package net.logstash.logback.marker;

import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.assertThatObject;

import java.util.LinkedHashMap;
import java.util.Map;
Expand Down Expand Up @@ -101,6 +102,47 @@ public void testToString() {
map.put("fieldName2", "fieldValue2");
assertThat(Markers.appendEntries(map).toString())
.isEqualTo("{fieldName1=fieldValue1, fieldName2=fieldValue2}");

}


/*
* LogstashMarkers are equals when same name, irrespective of their references
*/
@Test
public void testEqualsAndHashCode() {
assertThat(Markers.empty()).isEqualTo(Markers.empty());
assertThat(Markers.empty()).hasSameHashCodeAs(Markers.empty());

assertThatObject(
Markers.empty().and(Markers.empty()))
.isEqualTo(
Markers.empty());

assertThatObject(
Markers.empty().and(Markers.empty()))
.hasSameHashCodeAs(
Markers.empty());


assertThat(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")))
.isEqualTo(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")));

assertThat(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")))
.hasSameHashCodeAs(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")));


assertThat(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")))
.isEqualTo(
Markers.aggregate(MarkerFactory.getMarker("m2"), MarkerFactory.getMarker("m1")));

assertThat(
Markers.aggregate(MarkerFactory.getMarker("m1"), MarkerFactory.getMarker("m2")))
.hasSameHashCodeAs(
Markers.aggregate(MarkerFactory.getMarker("m2"), MarkerFactory.getMarker("m1")));
}
}