Forums - Thread Details
  • State Verified Answer
  • Replies 6 replies
  • Subscribers 320 subscribers
  • Views 892 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

  • 0

    What about CPF/Memory usage by apache/elasticsearch during upgrade process?

    Does any feature send email on creating the Lead? Eventually the email takes longer to be sent which may freeze the application.

    André Lopes
    Lampada Global
    Skype: andre.lampada
  • 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

  • 0 in reply to Francesca Shiekh

    Whenever an event happens SugarCRM tries to invoke any related logic hooks, if such they don't exist so nothing is execute.

    I agree that looking at sugarcrm.log under debug log.level is a kind of scary.

    As the timestamp are the same one in those records then I may say it is not the real issue.

    A better approach would be reviewing eventual sugarLogic formulas on Leads or related to Leads. Additionally Let us know the elapsed time between consecutives save event on Leads (log on initiating and finishing a specific logic_hook) on Leads.

    André Lopes
    Lampada Global
    Skype: andre.lampada
  • 0 in reply to André Lopes

    André Lopes,

    Thank you for your help. The timestamps are the same for those I included because that's how the lead begins, but the last set of operations, the one that gets logged hundreds of times goes on and on executing multiple times per second for a full 11seconds.

    11seconds for each lead on a batch of one thousand leads really adds up.

    Each of the Logic Hooks on Leads was disabled for this most recent test so they should have no effect on the timing.

    On a previous timing, as stated above, the logic hooks all completed in less than a second but there was an interval of about 1minute between the end of the last before-save and the beginning of the first after-save.

    I had the DBAs check the database while the import was running and nothing stood out.

    I have one field with a sugarLogic formula on leads :

        'event_attendance_c' =>
        array (
          'duplicate_merge_dom_value' => 0,
          'labelValue' => 'Event Attendance',
          'full_text_search' =>
          array (
            'enabled' => '0',
            'boost' => '1',
            'searchable' => false,
          ),
          'calculated' => 'true',
          'formula' => 'ifElse(equal($virtual_event_status_c,"Attended"),1,0)',
          'enforced' => 'true',
          'dependency' => '',
          'required' => false,
          'source' => 'custom_fields',
          'name' => 'event_attendance_c',
          'vname' => 'LBL_EVENT_ATTENDANCE',
          'type' => 'int',
          'massupdate' => false,
          'no_default' => false,
          'comments' => 'Rollup formula field',
          'help' => '',
          'importable' => 'false',
          'duplicate_merge' => 'disabled',
          'audited' => false,
          'reportable' => true,
          'unified_search' => false,
          'merge_filter' => 'disabled',
          'pii' => false,
          'len' => 255,
          'size' => '20',
          'enable_range_search' => false,
          'disable_num_format' => NULL,
          'min' => false,
          'max' => false,
          'id' => 'Leadsevent_attendance_c',
          'custom_module' => 'Leads',
        ),

     

    Two on Events:

        'num_enrolled' =>
        array (
          'required' => false,
          'name' => 'num_enrolled',
          'vname' => 'LBL_NUM_ENROLLED',
          'type' => 'int',
          'massupdate' => false,
          'no_default' => false,
          'comments' => '',
          'help' => '',
          'importable' => 'false',
          'duplicate_merge' => 'disabled',
          'duplicate_merge_dom_value' => 0,
          'audited' => false,
          'reportable' => true,
          'unified_search' => false,
          'merge_filter' => 'disabled',
          'full_text_search' =>
          array (
            'enabled' => '0',
            'boost' => '1',
            'searchable' => false,
          ),
          'calculated' => '1',
          'formula' => 'count($evnts_events_leads)',
          'enforced' => true,
          'len' => '255',
          'size' => '20',
          'enable_range_search' => false,
          'disable_num_format' => '',
          'min' => false,
          'max' => false,
        ),



        'attendance_total' =>
        array (
          'required' => false,
          'name' => 'attendance_total',
          'vname' => 'LBL_ATTENDANCE_TOTAL',
          'type' => 'int',
          'massupdate' => false,
          'no_default' => false,
          'comments' => '',
          'help' => '',
          'importable' => 'false',
          'duplicate_merge' => 'disabled',
          'duplicate_merge_dom_value' => 0,
          'audited' => false,
          'reportable' => true,
          'unified_search' => false,
          'merge_filter' => 'disabled',
          'full_text_search' =>
          array (
            'enabled' => '0',
            'boost' => '1',
            'searchable' => false,
          ),
          'calculated' => '1',
          'formula' => 'rollupSum($evnts_events_leads,"event_attendance_c")',
          'enforced' => true,
          'dependency' => '',
          'len' => '255',
          'size' => '20',
          'enable_range_search' => false,
          'disable_num_format' => '',
          'min' => false,
          'max' => false,
        ),

    and none on Campaigns.

    thank you!

    Francesca

  • 0 in reply to Francesca Shiekh

    André Lopes I removed the Sugar Logic calculations on the Events module and it completed in seconds!


    Thank you so much for putting me on the right path!

    Francesca