Forums - Thread Details
  • State Verified Answer
  • Replies 6 replies
  • Subscribers 319 subscribers
  • Views 902 views
  • Users 0 members are here
Forum Actions
Related

lead import, slow then partially fails

Francesca Shiekh

I am trying to import about 400 leads from a spreadsheet using the the Lead import process.

We have done things many times over the years but suddenly it is very slow, processes 200 leads in three hours then reports the import failed.

Oddly the leads it does import all have identical timestamps in the date_entered field.

I don't have any major changes recorded in my logs that would justify a change in behavior like this. Though there has been an uptick in people mass-updating leads at the same time.

I added logging to the logic hooks we have.

For the first minute or so things progress quickly, then I start seeing an interval of approx 1minute between the before save and the after save logic hooks.

There are no indications of slow queries or locks on the DB side.

The Elasticsearch server has some spikes in disk usage, but I don't think that's unusual.

I realize this is all very vague information, but any thoughts on what else could be happening to cause these issues? 

What else should I be looking at?

thank you,
FrancescaS

Parents Reply Children
  • 0 in reply to André Lopes

    Thank you André Lopes, I had not thought about the emails, I will check how notifications go out and ask my sysadmins to check CPF/Memory use by apache/elastic.

  • 0 in reply to André Lopes

    I tried an import of 25 leads in my Development environment with the log on debug and found that there are entries like this for each field of the spreadsheet 

    Localization translation of the lead data being entered

    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Localization: translating [Francesca] from UTF-8 into UTF-8
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Localization: translating [Shiekh] from UTF-8 into UTF-8

     

    Then lookups for the related Events (a custom module), Campaign (sugar OOB) and Users (for the assigned user).

     

    Followed by inserts into the audit tables:

    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][INFO] Query:INSERT INTO leads_audit(id,parent_id,event_id,field_name,data_type,before_value_string,after_value_string,date_created,created_by) VALUES('ef0b084e-41aa-11e9-ab5e-001a4a160170','ef08e65e-41aa-11e9-9f64-001a4a160170','ef093352-41aa-11e9-bc3d-001a4a160170','status','enum',NULL,'recycled','2019-03-08 14:02:38','2053ed63-d2dc-52e8-0049-4ddab9fc33f1')

    Update of the relationships

    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][INFO] Entered operation status: updating_relationships

    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][INFO] Left operation status: updating_relationships
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][INFO] Entered operation status: saving_related

    All of the above happens very quickly.

     

    And then HUNDREDS of these hook calls over and over again for a full 11s:

    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Leads::before_retrieve
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] SugarBean[Lead].load_relationships, Loading link (team_link).
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] SugarBean[Lead].load_relationships, Loading link (favorite_link).
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] SugarBean[Lead].load_relationships, Loading link (following_link).
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Retrieve Lead
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Campaigns::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Campaigns::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Campaigns::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Users::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Teams::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Teams::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Teams::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] SugarBean[Lead].load_relationships, Loading link (evnts_events_leads).
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: evnts_Events::before_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: evnts_Events::process_record
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: evnts_Events::after_fetch_query
    Fri Mar  8 08:03:22 2019 [32611][2053ed63-d2dc-52e8-0049-4ddab9fc33f1][DEBUG] Hook called: Leads::after_retrieve

    Why would the hooks be called over and over so many times?

    I don't have any custom hooks on evnt_Events, Users, or Campaigns. And ALL the hooks for the Leads were disabled for this test. 

    I am at a loss and we can't keep spending hours just to import a handful of Leads....

    Any help is appreciated.

    FrancescaS