[
https://issues.apache.org/jira/browse/IGNITE-29109?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18123849#comment-18123849
]
Nikolay Izhikov commented on IGNITE-29109:
------------------------------------------
{code:java}
package repro;
import java.lang.management.ManagementFactory;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.TreeMap;
import java.util.TreeSet;
import java.util.function.IntSupplier;
import com.sun.management.ThreadMXBean;
import org.apache.ignite.Ignite;
import org.apache.ignite.IgniteCache;
import org.apache.ignite.Ignition;
import org.apache.ignite.configuration.IgniteConfiguration;
import org.apache.ignite.internal.IgniteEx;
import
org.apache.ignite.internal.processors.cache.binary.CacheObjectBinaryProcessorImpl;
import org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi;
import org.apache.ignite.spi.discovery.tcp.ipfinder.vm.TcpDiscoveryVmIpFinder;
/**
* Reproducer: the binary marshaller rebuilds the class descriptor of {@code
TreeMap} and
* {@code TreeSet} on every write.
* <p>
* {@code BinaryContext} registers both classes with {@code
registerBinarilizableSystemClass}, which
* caches a descriptor built by {@code systemClassDescriptor(...)} with {@code
registered = false}.
* Every write then calls {@code registerClass} -> {@code registerDescriptor},
which builds a
* registered copy with {@code makeRegistered()} (a new {@code
BinaryClassDescriptor}, with reflective
* method look-ups that throw {@code NoSuchMethodException}) and offers it with
{@code putIfAbsent}.
* The unregistered entry is already there, so the copy is dropped and the work
repeats on the next
* write.
* <p>
* {@code BinaryTreeMap}, the write replacement of {@code TreeMap}, is
registered the same way.
* <p>
* The program measures one value class per collection type, first as Ignite
ships, then after
* replacing the three cached descriptors ({@code TreeMap}, {@code TreeSet},
{@code BinaryTreeMap})
* with registered ones through reflection, which is what the proposed fix does.
*/
public final class TreeCollectionDescriptorRepro {
private static final int ROUNDS = 5;
private static final int OPS = 20_000;
private static long sink;
private static final ThreadMXBean THREADS = (ThreadMXBean)
ManagementFactory.getThreadMXBean();
/** A value with one field, written by Ignite in OBJECT mode. */
public static final class Holder {
private final Object field;
Holder(Object field) {
this.field = field;
}
}
private TreeCollectionDescriptorRepro() {
}
/**
* Runs the measurement on a single embedded node.
*
* @param args not used
* @throws Exception if the node cannot be started or the internals cannot
be reached
*/
public static void main(String[] args) throws Exception {
TcpDiscoveryVmIpFinder ipFinder = new
TcpDiscoveryVmIpFinder().setAddresses(List.of("127.0.0.1:49500"));
IgniteConfiguration cfg = new IgniteConfiguration()
.setIgniteInstanceName("repro")
.setDiscoverySpi(new
TcpDiscoverySpi().setLocalAddress("127.0.0.1").setLocalPort(49500)
.setLocalPortRange(1).setIpFinder(ipFinder));
try (Ignite ignite = Ignition.start(cfg)) {
System.out.println("Ignite " + ignite.version() + ", Java " +
Runtime.version()
+ ", " + Runtime.getRuntime().availableProcessors() + "
CPUs");
IgniteCache<Integer, Holder> cache =
ignite.getOrCreateCache("repro");
printHeader();
measureAll(ignite, cache, "as shipped");
Map<Class<?>, Object> descByCls = descriptorCache(ignite);
Class<?> binaryTreeMap =
Class.forName("org.apache.ignite.internal.binary.BinaryTreeMap");
for (Class<?> cls : List.of(TreeMap.class, TreeSet.class,
binaryTreeMap)) {
Object desc = descByCls.get(cls);
Method registered =
desc.getClass().getDeclaredMethod("registered");
Method makeRegistered =
desc.getClass().getDeclaredMethod("makeRegistered");
registered.setAccessible(true);
makeRegistered.setAccessible(true);
System.out.println("cached descriptor of " + cls.getName() + ":
registered=" + registered.invoke(desc));
descByCls.put(cls, makeRegistered.invoke(desc));
}
measureAll(ignite, cache, "descriptors registered");
}
}
private static void printHeader() {
System.out.printf("%-24s %-28s %22s %22s %22s%n", "setting", "field
value", "toBinary", "cache.put", "cache.get");
}
private static void measureAll(Ignite ignite, IgniteCache<Integer, Holder>
cache, String setting) {
TreeMap<String, Long> twelve = new TreeMap<>();
for (int i = 0; i < 12; i++) {
twelve.put("key-" + i, (long) i);
}
Object[][] cases = {
{"empty HashMap", new HashMap<String, Long>()},
{"empty ArrayList", new ArrayList<String>()},
{"empty TreeMap", new TreeMap<String, Long>()},
{"empty TreeSet", new TreeSet<String>()},
{"TreeMap with 12 entries", twelve},
};
for (Object[] c : cases) {
Holder holder = new Holder(c[1]);
double[] toBinary = perOp(() ->
System.identityHashCode(ignite.binary().toBinary(holder)));
double[] put = perOp(() -> {
cache.put(1, holder);
return 1;
});
cache.put(1, holder);
double[] get = perOp(() -> System.identityHashCode(cache.get(1)));
System.out.printf("%-24s %-28s %8.0f ns %8.0f B %8.0f ns %8.0f B
%8.0f ns %8.0f B%n", setting, c[0],
toBinary[0], toBinary[1], put[0], put[1], get[0], get[1]);
}
}
/** @return {median nanoseconds per op, median bytes allocated on this
thread per op}. */
private static double[] perOp(IntSupplier op) {
for (int i = 0; i < 2 * OPS; i++) {
sink += op.getAsInt();
}
double[] nanos = new double[ROUNDS];
double[] bytes = new double[ROUNDS];
for (int r = 0; r < ROUNDS; r++) {
long startBytes = THREADS.getCurrentThreadAllocatedBytes();
long start = System.nanoTime();
for (int i = 0; i < OPS; i++) {
sink += op.getAsInt();
}
nanos[r] = (System.nanoTime() - start) / (double) OPS;
bytes[r] = (THREADS.getCurrentThreadAllocatedBytes() - startBytes)
/ (double) OPS;
}
Arrays.sort(nanos);
Arrays.sort(bytes);
return new double[] {nanos[ROUNDS / 2], bytes[ROUNDS / 2]};
}
@SuppressWarnings("unchecked")
private static Map<Class<?>, Object> descriptorCache(Ignite ignite) throws
Exception {
Object binaryContext = ((CacheObjectBinaryProcessorImpl) ((IgniteEx)
ignite).context().cacheObjects()).binaryContext();
Field descByCls =
binaryContext.getClass().getDeclaredField("descByCls");
descByCls.setAccessible(true);
return (Map<Class<?>, Object>) descByCls.get(binaryContext);
}
}
{code}
> TreeMap/TreeSet class descriptor is rebuilt on every binary write since
> 2.18.0 (regression of IGNITE-26061)
> -----------------------------------------------------------------------------------------------------------
>
> Key: IGNITE-29109
> URL: https://issues.apache.org/jira/browse/IGNITE-29109
> Project: Ignite
> Issue Type: Bug
> Reporter: Nikolay Izhikov
> Assignee: Nikolay Izhikov
> Priority: Major
> Labels: ise
> Fix For: 2.19
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> h3. Summary
> Since 2.18.0 every binary write of a {{java.util.TreeMap}} or
> {{java.util.TreeSet}} rebuilds its {{BinaryClassDescriptor}} by reflection.
> An empty {{TreeMap}} costs ~25x more to marshal than in 2.17.0 (~6 µs vs
> ~0.26 µs); {{cache.put}} is ~10x slower and {{cache.get}} of a {{TreeMap}}
> value ~9x slower. {{HashMap}} and {{ArrayList}} are not affected. The compute
> closure wrappers {{GridClosureProcessor.C1/C1MLA/C2/C2MLA/C4/C4MLA}} take the
> same slow path. Reported on the dev list by a user; reproducer attached.
> h3. Measurements
> Reporter's reproducer (attached), one embedded server node, single thread,
> median of 5 rounds of 20 000 ops after warm-up, JDK 17, 12 CPUs, ns/op:
> ||Field value||2.17.0 toBinary||2.18.0 toBinary||2.17.0 put||2.18.0
> put||2.17.0 get||2.18.0 get||
> |empty HashMap|395|521|1602|2669|1142|1673|
> |empty ArrayList|289|292|865|957|472|516|
> |empty TreeMap|261|*6221*|985|*9416*|532|*4728*|
> |empty TreeSet|364|*5722*|990|*8563*|587|556|
> |TreeMap, 12 entries|1098|*6956*|1873|*10208*|1139|*5335*|
> h3. Root cause
> Introduced by IGNITE-26061 (commit 06a557b2e4, PR #12230).
> # {{BinaryContext}} constructor now calls
> {{registerBinarilizableSystemClass}} for {{BinaryTreeMap}}, {{TreeMap}} and
> {{TreeSet}}; {{GridClosureProcessor.onBinaryContextCreated}} does the same
> for the six closure wrappers.
> # {{registerBinarilizableSystemClass}} puts {{systemClassDescriptor(...)}}
> into {{descByCls}}. That descriptor is created with {{registered = false}}.
> # On every write {{registerClass}} sees {{!desc.registered()}} and calls
> {{registerDescriptor}}, which builds a registered copy with
> {{desc.makeRegistered()}} (full {{BinaryClassDescriptor}} constructor with
> reflective look-ups) and offers it with {{descByCls.putIfAbsent(...)}}.
> # The unregistered entry is already present, so {{putIfAbsent}} returns it
> and the registered copy is discarded. The next write repeats the work.
> Before IGNITE-26061 these classes were listed by name in
> {{BINARYLIZABLE_SYS_CLSS}} and nothing was in {{descByCls}} before the first
> write, so the first {{putIfAbsent}} cached the registered descriptor.
> h3. Fix
> Cache the descriptor in the registered state:
> {code:java}
> public void registerBinarilizableSystemClass(Class<?> cls) {
> String clsName = cls.getName();
> descByCls.put(cls, systemClassDescriptor(cls, clsName, new
> BinaryReflectiveSerializer()).makeRegistered());
> }
> {code}
> With the fix the reproducer shows empty {{TreeMap}} at 453 ns toBinary / 1119
> ns put / 580 ns get, i.e. back at 2.17.0 level. A regression test is added to
> {{BinaryContextPredefinedTypesTest}} asserting that the cached descriptors of
> these system classes are registered and that {{registerClass}} returns the
> cached instance.
> h3. Reproducer
> {{treemap-descriptor-repro.zip}} (attached): {{mvn -q compile exec:exec}}
> runs against 2.18.0, {{-Dignite.version=2.17.0}} for comparison. See its
> README.md.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
