Memory leak in lazy relation

[MeiK2333]

Issue type:

[x] bug report
[ ] feature request
[ ] documentation issue

Database system/driver:

[ ] cordova
[ ] mongodb
[ ] mssql
[ ] mysql / mariadb
[ ] oracle
[x] postgres
[ ] cockroachdb
[x] sqlite
[ ] sqljs
[ ] react-native
[ ] expo

TypeORM version:

[x] latest
[ ] @next
[ ] 0.x.x (or put your version here)

Steps to reproduce or a small repository showing the problem:

import 'reflect-metadata';
import { Entity, PrimaryGeneratedColumn, Column, createConnection, Index, ManyToOne, OneToMany } from "typeorm";

type Lazy<T extends object> = Promise<T> | T;

@Entity()
class Bind {
  @PrimaryGeneratedColumn()
  id: number;

  @ManyToOne(type => Source, source => source.bind, { lazy: true })
  source: Lazy<Source>
}

@Entity()
@Index(['problemId', 'source'])
class Problem {
  @PrimaryGeneratedColumn()
  id: number;

  @Column()
  problemId: string

  @ManyToOne(type => Source, source => source.problem, { lazy: true })
  source: Lazy<Source>
}

@Entity()
class Source {
  @PrimaryGeneratedColumn()
  id: number;

  @OneToMany(type => Problem, problem => problem.source, { lazy: true })
  problem: Lazy<Problem[]>

  @OneToMany(type => Bind, bind => bind.source, { lazy: true })
  bind: Lazy<Bind[]>
}

(async () => {
  const connection = await createConnection({
    type: "postgres",
    host: "localhost",
    port: 5432,
    username: "postgres",
    password: "password",
    database: "StepByStep",
    entities: [
      Bind, Source, Problem
    ],
    synchronize: true,
    logging: false
  })

  const source = new Source();
  await connection.manager.save(source);

  const bind = new Bind();
  bind.source = source;
  await connection.manager.save(bind);


  const repository = connection.getRepository(Problem);
  for (let i = 0; i < 100; i++) {
    {
      // Memory leak code
      console.time(`create ${i}`);
      const problem = repository.create({
        source,
        problemId: String(i)
      });
      await repository.save(problem);
      console.timeEnd(`create ${i}`);
    }
    {
      // pass code
      console.time(`new ${i}`);
      const problem = new Problem();
      problem.source = source;
      problem.problemId = String(i);
      await repository.save(problem);
      console.timeEnd(`new ${i}`);
    }
  }
})();

output:

create 0: 13.096ms
new 0: 4.519ms
create 1: 6.676ms
new 1: 4.373ms
create 2: 5.298ms
new 2: 4.338ms
create 3: 12.688ms
new 3: 4.261ms
create 4: 12.086ms
new 4: 4.253ms
create 5: 35.003ms
new 5: 4.682ms
create 6: 59.895ms
new 6: 4.010ms
create 7: 311.416ms
new 7: 3.859ms
create 8: 527.165ms
new 8: 3.740ms
create 9: 3783.229ms
new 9: 3.806ms
create 10: 8092.808ms
new 10: 3.579ms

<--- Last few GCs --->

[28832:0x110008000]    39560 ms: Scavenge 2042.0 (2050.6) -> 2041.4 (2051.1) MB, 4.6 / 0.0 ms  (average mu = 0.135, current mu = 0.009) allocation failure 
[28832:0x110008000]    41210 ms: Mark-sweep 2042.1 (2051.1) -> 2041.3 (2050.6) MB, 1649.4 / 0.0 ms  (average mu = 0.096, current mu = 0.066) allocation failure scavenge might not succeed
[28832:0x110008000]    41217 ms: Scavenge 2042.2 (2050.6) -> 2041.5 (2051.1) MB, 4.4 / 0.0 ms  (average mu = 0.096, current mu = 0.066) allocation failure 


<--- JS stacktrace --->

==== JS stack trace =========================================
......
FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
......

I tried postgres and sqlite, the result is the same. There is a huge performance gap when using new and create.

English is not my native language; please excuse typing errors.

[imnotjames]

Did a bit of experimentation & setting up a test case for this..

Does not fail when you're just re-saving the created model over and over.
Also does not fail when you create without saving - so it's something to do with the save operation here.

The create sets the dunder-source (__source__) property (probably should eventually move away from this notation..) for the "resolved" source.

In the new method to create a model it sets the source property directly.

This issue does NOT occur if you set the __source__ directly:

            const problem = new Problem();
            problem.problemId = String(i);
            (problem as any).__source__ = source;
            await repository.save(problem);

---

After changing the test up a bit & timing them separately, both the create AND the save take an increasing amount of time as they're iterating upwards.. the create increases in time before the save.

---

After doing some profiling - replacePropertyNames is taking a ton of time & is called very frequently - same with SelectQueryBuilder... somewhere. Not sure. And more than half the time is spent sitting iwth node outside of any actual code.

[imnotjames]

Holy wowza, something is causing this to double the number of queries for Bind and Problem each iteration. By iteration 12 there's over 5000 queries that have to be run as part of a save.

That's definitely not right..

[imnotjames]

Looks like the initial call in create to this.plainObjectToEntityTransformer.transform(mergeIntoEntity, plainObjectOrObjects, metadata, true); is the main-ish cause..

The last parameter is getLazyRelationsPromiseValue - if we switch it to false things don't blow up - but that may cause other issues down the line. This prevents the recursion.. need to figure out what reason this existed.

As far as the out of memory.. I think that's a side effect. There's definitely some places where we can improve the GC characteristics but loading millions of the same model seems to be a problem.

[salemhilal]

I think I'm seeing a similar problem in Sql.js (which is just sqlite transpiled to web assembly). I'm using it to write tests, and there seems to be an infinite loop of queries after my query returns in my test. The queries all looked like they were loading related columns.

Some very hacky debugging got me to this Object.values loop in RawSqlResultsToEntityTransformer:

typeorm/src/query-builder/transformer/RawSqlResultsToEntityTransformer.ts

Line 53 in 0b54222

!Object.values(entity).every((value) => value === null)

The entity is iterated over as part of some logic to transform the results into an entity. It looks like by iterating over the entity, more relation queries are kicked off and are attempted to be loaded. I don't really see anything checking whether or not the entity's properties are lazy in that loop like I do in PlainObjectToNewEntityTransformer.

[salemhilal]

@pleerock sorry for the direct @ here. Is there a mechanism in RawSqlResultsToEntityTransformer that prevents lazy relations from getting unnecessarily queried? I'm not seeing anything. My next step is to just tear out all the lazy relations we're using, but if I can avoid a refactor like that, it would save me a lot of time.

[salemhilal]

Ok, I did some more debugging and I think I found the source of this bug @pleerock.
In short: When raw SQL is hydrated into an entity, it looks like the lazy relations are initially set to undefined. Since those keys get defined at all, they are visible to iterators like Object.keys and Object.values. When Object.values gets called on the entity, it inadvertently triggers the lazy loading request for that property. This appears to loop infinitely, although I'm not sure if it's because each subsequent request hits the same logic, or because bi-directionally-related entities end up loading each other.

Let me know if you'd like me to open up a separate issue for this.

Details

It looks like, by default, defining a property doesn't make it visible to Object.values by default (there is an enumerable property you can set to true if you'd like it to be visible).

RelationLoader.ts uses Object.defineProperty to implement lazy relations, and at first glance you'd expect those properties to be unenumerated.

However, for some reason, entities in RawSqlResultsToEntityTransformer end up with lazy relation keys and values set. On the line in transform which I mentioned above in a previous comment:

you can see this entity (Meter) having lazy relations (meteredComponents and vendor) defined as promises (I know it's a little hard to pick through):

and this call to Object.values in turn triggers a .get() call which kicks off the lazy relation's logic (<anonymous> here is the callback to Object.values):

I dug in a little further. I stepped into transformRawResultsGroup which calls EntityMetadata.create. As part of that, it sets up lazy relations here. Before that loop gets called, ret has all the properties of my entity, but they're undefined since they presumably haven't been hydrated yet.

HOWEVER: look at what Object.keys does to that value:

That made me wonder if Object.defineProperty inherits the visibility of any keys that are already on the object. It turns out that yes, it does:

In other words, by defining the keys for a lazy relationship on an entity before the lazy relationship is created, those lazy relations inadvertently get called when hydrating results. I haven't yet figured out why those properties are instantiated to undefined or why this only seems to happen with Sql.js (and not with our production MySQL-flavored database), but this feels like enough digging to identify the issue.

If you're curious, click here to see the source for MeterEntity

My MeterEntity looks like this (S_Meter is a generated type to make sure the entity agrees with our GraphQL schema):

@Entity("meter")
export class MeterEntity implements S_Meter {
    @PrimaryColumn()
    id!: string;

    @Column({ name: "is_archived" })
    isArchived!: boolean;

    @Column("text", { nullable: true })
    description!: string | null;

    @Column("varchar", { name: "meter_type" })
    meterType!: MeterType;

    @Column({ name: "is_incremental" })
    isIncremental!: boolean;

    @Column("varchar", { name: "unit_name", nullable: true })
    unitName!: string | null;

    @Column("varchar")
    name!: string;

    @Column("varchar", { name: "display_name" })
    displayName!: string;

    @CreateDateColumn({ name: "created_at" })
    createdAt!: string;

    @ManyToOne(() => VendorEntity, (vendor) => vendor.meters)
    @JoinColumn({ name: "vendor_id" })
    vendor!: Promise<VendorEntity>;

    @OneToMany(() => MeteredComponentEntity, (mc) => mc.meter)
    meteredComponents!: Promise<MeteredComponentEntity[]>;
}

[orcwarrior]

Thanks, @imnotjames and @salemhilal for debugging the issue it really helped me to pin it down!
Seems like while debugging this was a real hell, the fix was pretty easy @salemhilal sums it up in the previous post.
If somebody needs to patch it locally before the fix gets merged, code like this should help:

const orgObjectDefineProperty = Object.defineProperty;

Object.defineProperty = (obj, property, attributes) => orgObjectDefineProperty(obj, property, {
    ...attributes,
    enumerable: (attributes.enumerable === true)
});

I spend quite some time, trying to replicate the issue by writing a test case for it to fail.
Unfortunately wasn't able, while having a couple of tries.
The reason for the issue to happen is that setting all properties of entity instance to undefined - I'm not familiar with TypeOrm codebase, so I wasn't able to find a reason for that happening.
Those undefined fields later forces enumerable to have true value for the property which eventually leads to all relations getting queried until the memory is no more 😅