Orm creating CPU spikes

[bvallelunga]

Node Version: v0.10.23 Mysql Version: 5.5.34-0ubuntu0.12.10.1 Package Version: 2.1.3

var orm = require("orm");
var modts = require('orm-timestamps');
var paging = require("orm-paging");

function configure(db, models, callback) {
    /* Settings */
    db.settings.set("properties.primary_key", "id");
    db.settings.set("instance.cache", false);
    db.settings.set("instance.autoSave", false);
    db.settings.set("instance.autoFetch", true);
    db.settings.set("instance.autoFetchLimit", 2);

    /* Use Plugins */
    db.use(paging);
    db.use(modts, {
        persist: true,
        createdProperty: 'created',
        modifiedProperty: 'modified',
        dbtype: {
            type: 'date',
            time: true
        },
        now: function() {
            return new Date();
        }
    });

    /* Define Models */
    models.pricing = require("./pricing")(db, models);
    models.notifications = require("./notifications")(db, models);
    models.payments = require("./payments")(db, models);
    models.tracking = require("./tracking")(db, models);

    models.users = require("./users")(db, models);

    models.organizations = require("./organizations")(db, models);
    models.organizations.permissions = require("./organizations/permissions")(db, models);
    models.organizations.roles = require("./organizations/roles")(db, models);

    models.documents = require("./documents")(db, models);
    models.documents.permissions = require("./documents/permissions")(db, models);
    models.documents.roles = require("./documents/roles")(db, models);

    /* Associations */
    models.users.hasOne("pricing", models.pricing, {reverse: 'users'});
    models.organizations.hasOne("pricing", models.pricing, {reverse: 'organizations'});

    models.tracking.hasOne("user", models.users);
    models.tracking.hasOne("organization", models.organizations);

    models.notifications.hasOne("user", models.users, {reverse: 'notifications'});
    models.notifications.hasOne("organization", models.organizations, {reverse: 'notifications'});

    models.payments.hasOne("user", models.users, {reverse: 'payments'});
    models.payments.hasOne("organization", models.organizations, {reverse: 'payments'});

    models.organizations.hasOne("owner", models.users, {required: true});
    models.organizations.roles.hasOne("organization", models.organizations, {reverse: 'roles', required: true});
    models.organizations.roles.hasOne("user", models.users, {reverse: "organizations", required: true});
    models.organizations.roles.hasOne("permission", models.organizations.permissions, {required: true});

    models.documents.hasOne("owner", models.users, {required: true});
    models.documents.roles.hasOne("document", models.documents, {reverse: 'roles', required: true});
    models.documents.roles.hasOne("user", models.users, {required: true});
    models.documents.roles.hasOne("permission", models.documents.permissions, {required: true});

    db.sync();

    if(callback) callback();
}

exports.init = function(main, callback, withValues) {
    orm.connect(config.orm, function (error, db) {
        if(!error) {
            var models = {};
            configure(db, models, function() {
                /* Attach To Main */
                if(main) {
                    main.db = db;
                    main.models = models;
                }

                /* Callback Function */
                if(callback) {
                    if(withValues != false) {
                        callback(db, models);
                    } else {
                        callback();
                    }
                }
            });
        }
    });
}

orm.express(config.orm, {
    define: function (db, models, next) {
        configure(db, models, next);
    }
});

[bvallelunga]

@dresende could you help me debug this problem?

[bvallelunga]

@devpascoe what do you think about this bug? Is it a bug in my code or the orm?

[bvallelunga]

Can @dresende, @devpascoe or any other developer familiar with the internals of this module please help me. I just changing databases to postgres to check to see if it was the mysql driver was the problem. While using postgres I saw the same cpu spikes I saw while using mysql. You can see that the cpu is at 94%.

Here is an updated version of my code

var orm = require("orm");
var modts = require('orm-timestamps');
var paging = require("orm-paging");

function configure(db, models, init, callback) {
    /* Settings */
    db.settings.set("properties.primary_key", "id");
    db.settings.set("instance.cache", false);
    db.settings.set("instance.autoSave", false);
    db.settings.set("instance.autoFetch", true);
    db.settings.set("instance.autoFetchLimit", 2);

    /* Use Plugins */
    db.use(paging);
    db.use(modts, {
        persist: true,
        createdProperty: 'created',
        modifiedProperty: 'modified',
        dbtype: {
            type: 'date',
            time: true
        },
        now: function() {
            return new Date();
        }
    });

    /* Define Models */
    models.pricing = require("./pricing")(db, models);
    models.notifications = require("./notifications")(db, models);
    models.payments = require("./payments")(db, models);
    models.tracking = require("./tracking")(db, models);

    models.users = require("./users")(db, models);
    models.users.feedback = require("./users/feedback")(db, models);

    models.organizations = require("./organizations")(db, models);
    models.organizations.permissions = require("./organizations/permissions")(db, models);
    models.organizations.roles = require("./organizations/roles")(db, models);

    models.documents = require("./documents")(db, models);
    models.documents.permissions = require("./documents/permissions")(db, models);
    models.documents.roles = require("./documents/roles")(db, models);

    /* Associations */
    models.users.hasOne("pricing", models.pricing, {reverse: 'users'});
    models.organizations.hasOne("pricing", models.pricing, {reverse: 'organizations'});

    models.users.feedback.hasOne("user", models.users, {reverse: 'feedbacks'});

    models.tracking.hasOne("user", models.users);
    models.tracking.hasOne("organization", models.organizations);

    models.notifications.hasOne("user", models.users, {reverse: 'notifications'});
    models.notifications.hasOne("organization", models.organizations, {reverse: 'notifications'});

    models.payments.hasOne("user", models.users, {reverse: 'payments'});
    models.payments.hasOne("organization", models.organizations, {reverse: 'payments'});

    models.organizations.hasOne("owner", models.users, {required: true});
    models.organizations.roles.hasOne("organization", models.organizations, {reverse: 'roles', required: true});
    models.organizations.roles.hasOne("user", models.users, {reverse: "organizations", required: true});
    models.organizations.roles.hasOne("permission", models.organizations.permissions, {required: true});

    models.documents.hasOne("owner", models.users, {required: true});
    models.documents.roles.hasOne("document", models.documents, {reverse: 'roles', required: true});
    models.documents.roles.hasOne("user", models.users, {required: true});
    models.documents.roles.hasOne("permission", models.documents.permissions, {required: true});

    if(init && config.orm.reset) {
        /* Drop All Tables */
        db.drop(function(error) {
            lib.error.capture(error);

            /* Sync With Database */
            db.sync(function(error) {
                lib.error.capture(error);

                /* Preload Data */
                require("./preload")(models);
            });
        });
    }

    if(callback) callback();
}

exports.init = function(main, callback, withValues, init) {
    orm.connect(config.orm, function (error, db) {
        if(!error) {
            var models = {};
            configure(db, models, init, function() {
                /* Attach To Main */
                if(main) {
                    main.db = db;
                    main.models = models;
                }

                /* Callback Function */
                if(callback) {
                    if(withValues != false) {
                        callback(db, models);
                    } else {
                        callback();
                    }
                }
            });
        } else {
            lib.error.capture(error);
        }
    });
}

exports.express = orm.express(config.orm, {
    define: function (db, models, next) {
        configure(db, models, false, next);
    }
});

@dresende and @devpascoe do you see anything wrong in my code that could have caused the cpu spikes?

[bvallelunga]

@dxg, @Gamaroff, @opio can you please look at this issue and tell me if the problem lies in my code or the module. Sorry for calling all of you guys out but I really need this fixed and would hate to go to another orm. Thank you in advance for all the help you will bring.

[notheotherben]

Could well be nothing more than that your database has a very large number of relationships and autoFetch: true. Because of the way ORM handles relationships, this means that one additional query is executed for each relationship when fetching a model.

My recommendation would be to try first disabling any plugins you're using (paging and timestamp), commenting out as many models and relationships as possible, and then incrementally reintroducing them to see the effect it has. By the looks of it, one of your event handlers is the culprit for a large amount of processing time - so my first guess would be one of the plugins (which introduce their own event handlers much of the time) or a hook you're using in one of the models.

Also, please keep in mind that many of the developers of this project are on holiday at the moment, and those that aren't contribute in their spare time - we try to help out where we can, but the price everyone pays is that the support comes in the form of advice, and may take its time in coming. In future, refrain from tagging every contributor to the module in your issues and rather keep updating them with information as you get it (I notice you have done so), it's more likely to get you a fast response.

Hope you manage to solve the problem, and good luck

[bvallelunga]

thanks for the advice and I will update this issue when I have more information

[bvallelunga]

@SPARTAN563, after running some test I found that my cpu shoots to 100+% and holds when I update a instance while in a method function

Example: Calling the join method

req.models.documents.find({
    pub_id: req.param("document")
}, function(error, documents) {
    documents[0].join(req.session.user, 2, function(access, permission) {
                 ....
    });
});

Documents Model

module.exports = function (db, models) {
    return db.define("documents", {
        name: {
            type: "text",
            required: true
        },
        content: {
            type: "object",
            big: true
        },
        viewed: {
            type: "number",
            required: true,
            defaultValue: 0
        },
    }, { 
        methods: {
            join: function(user, permission, callback) {
                _this = this;
                models.documents.roles.find({
                    user_id: user.id,
                    document_id: _this.id
                }, 1, function(error, documents) {
                    if(!error) {
                        if(documents.empty) {
                            if(!_this.private) {
                                models.documents.roles.create({
                                    user_id: user.id,
                                    user_pub_id: user.pub_id,
                                    document_id: _this.id,
                                    document_pub_id: _this.pub_id,
                                    permission_id: permission,
                                    viewed: 1
                                }, lib.error.capture);
                                callback(true, {
                                    owner: false,
                                    readonly: false
                                });
                            } else {
                                callback(false);
                            }
                        } else {
                            if(documents[0].access) {
                                _this.save({
                                    viewed: _this.viewed + 1
                                }, lib.error.capture);

                                documents[0].save({
                                    viewed: documents[0].viewed + 1
                                }, lib.error.capture);

                                callback(true, {
                                    owner: documents[0].permission.owner,
                                    readonly: documents[0].permission.readonly
                                });
                            } else {
                                callback(false);
                            }
                        }
                    } else {
                        callback(false, false);
                        lib.error.capture(error);
                    }
                });
            }
        }
    });
}

[notheotherben]

Sounds to me like you are creating an infinite recursion, or an O(n^m) recursion. My recommendation would be to flatten your call structure so that you only need to make a few queries as opposed to one per insert.

Keep in mind that ORM supports passing arrays to model.insert for insertion of multiple objects, so you can build up an array of objects to insert and then make one request to insert them all - which should reduce your CPU usage.

[bvallelunga]

@SPARTAN563 do you mind giving an example using my code above. I am still confused on how my code creates a infinite recursion? I have also never seen any examples of code using model.insert. What is the difference between model.insert and model.create?

[notheotherben]

Unfortunately I haven't got the time or information necessary to do so, my guess would be that there is something in another model which is calling join when it is saved, or when a property is accessed etc.

Another way you could go about debugging it is to insert a console.log('Here I am...') or console.trace() within join and see if it is getting called more than once, if it isn't then I'd start looking deeper.

Obviously, that is all working on the assumption that there is a loop, it could just be that you're doing a large number of operations and it's taking ORM time to complete them because of the way it's designed - take a look at the Instance.js internal save methods and you'll see that there are plenty of places for unexpected queries to sneak in. If you're using hooks as well, this can quickly result in a recursive nightmare.

And yeah, sorry, I meant model.create - been working on a different ORM for the past few months which aliases create and insert.

[bvallelunga]

i found the loop, @SPARTAN563 thank you very much

[notheotherben]

Very glad to hear that, good luck with the rest of your project.

[bvallelunga]

thank you very much. @SPARTAN563 this bug you helped me with is for a company I am cofounding (http://laborate.io). The company essentially provides a suite of products that enable users to collaborate in realtime, you can think of it as google docs for everything google docs doesnt do (coding, notetaking, math, etc). The company is still in beta but when we launch our paid subscriptions I will give you a top tier account for free. I am very grateful for the help you have given me and the community. Thank You.!

[notheotherben]

Sounds interesting, I'll keep my eye on it. And thank you, glad I could be of some help