Server start & Message Log

[Guillaume Galtier]

Hi guys !

I'm trying to understand why the starting of our TM1 server has recently increased.
Looking at the log I can see this:

Code: Select all

....
5296   []   INFO   2013-01-10 17:53:14.285   TM1.Server   Processing feeders for cube "Inventory"
4484   []   INFO   2013-01-10 17:56:02.438   TM1.Cube.Dependency   Adding cube dependency: Cube 'Inventory' depends on cube '}ElementAttributes_Version Inventory'.
4484   []   INFO   2013-01-10 17:56:03.093   TM1.Cube.Dependency   Adding cube dependency: Cube 'Inventory' depends on cube '}ElementAttributes_Period'.
5296   []   INFO   2013-01-10 18:25:57.651   TM1.Server      Feeders created in cube "Inventory": new 32183290, duplicate 0, ignored 0
5296   []   INFO   2013-01-10 18:25:57.651   TM1.Server   Processing feeders for cube "Inventory_OLD"
....

One of the task is taking about 30min but I'm not sure how to interpret it.
Is it the "Adding cube dependency" task which is taking 30min or the next one ?

From my understanding it is the "Adding cube dependency" action, but in this case, is it normal that it takes so much time ?

Other question: What means the "new 32183290" on the "Feeders created in cube..." row ?

Thanks in advance
Guillaume

[Duncan P]

Adding cube dependency appears in the log whenever a calculation of a cell from one cube uses a value in another cube where there is not already a dependency declared between the cubes. Normally the adding of the dependency itself does not take time. The reason your attention is drawn to it is that it appears as one of the only log entries in some other long-running process such as processing feeders for a cube or constructing a view.

The exception is when you have multiple threads. Adding a cube dependency to a cube takes out a full lock on the cube which will only be given when all other threads have finished reading from the cube in question. During server start-up this should not be happening, unless you have enabled multi-threaded cube load. During load additional cube dependencies are only added in processing conditional feeders, where any of the arguments of the DB statement on the right side of the feeder use data from elsewhere, and in that case you should (as advised in the documentation) definitely not be using multi-threaded load.

This add cube dependency locking problem is incidentally why parallel CubeViewConstruct calls started by TM1RunTI.exe can end up running sequentially, but it can be avoided by adding the cube dependencies up front.

EDIT: and BTW the number 32183290 is the number of fed cells added. That's 32 million. Is that what you expect or has something happened to increase that number recently?

[mattgoff]

Each line shows the time the milestone was reached (start or finish for long tasks like feeders). You can see several lines above when feeder processing started. 17:53:14 start, 18:25:57 end. = 32m43s. IMHO that's a pretty long time for 32M feeders. But, variations in model and servers make that assessment pretty meaningless-- your best bet is Duncan's suggestion: since it sounds like that time has increased, have you changed your model at all?

Matt

[Duncan P]

I'm not sure that I explained myself that well.

The only information you can get from the log is this

• Processing feeders for cube "Inventory" took 32 minutes and 43 seconds.
  During that time two dependencies were added - after 2 minutes and 48 seconds and after 2 minutes and 49 seconds.

You are not told how long it took to add the dependencies and it is probable, given that we are in server start-up, that it was almost instantaneous.

The thing to look at is the feeders for "Inventory" and if they, or any feeders from the cells they feed (and so on) read calculated or aggregated data that is taking a long time.

[Gabor]

Did you try to manually reorder the dims in your feeder target cube? The automatic reordering does not give much benefit.
If you can get RAM usage down, this will have an impact on feeding time as well.
I assume the feeder rule itself is already optimized ...

[Guillaume Galtier]

Thank you guys for your clear explanations, I understood!

The model has effectively been updated recently. The cube "Inventory" has been rebuilt adding new dims, new rules and feeders (conditionnal feeders).
For information, the MaximumCubeLoadThreads option into the cfg is set to 1.

I've already reordered the dimensions for this cube but using the automatic reordering. Will try a manual reordering.

I've tried to optimize my rules and feeders, but it seems I still have to work on this side.

[Gabor]

My personal preference, how to develop & test complex feeders comes from times without any tracing tool in TM1.
1. Ensure the fed target cube has no real data in, maybe create a dummy version
2. Use 2 lines in rule of fed cub only:
Skipcheck;
[] = N: 1;
3. Start to work on your feeder statements in source cube
4. Turn on zero suppression in target cube, calculate and see fed cells
Any cell without feeding will disappear, you can start your check from consolidations and drill down to leaf elements.

Every new test needs to start with unloading the target cube of course, "PersistentFeeders=F" shall be used as well.

[Wim Gielis]

Hello all

Sorry for hijacking this thread - if not appropriate can a Moderator move the topic please?

In today's server message log at the customer, I see:

2024 [] INFO 2013-02-13 06:19:05.518 TM1.Server Feeders created in cube "INPUT CC": new 235727, duplicate 55416, ignored 0
2024 [] INFO 2013-02-13 06:19:05.518 TM1.Server Feeders created in cube "REP GLOBAL": new 987840, duplicate 5927040, ignored 0
2024 [] INFO 2013-02-13 06:19:05.518 TM1.Server Feeders created in cube "REP MNGNT": new 73, duplicate 133, ignored 0

I think that I never got to see these kind of messages.

Does anyone have more info on the "duplicate" and "ignored" parts?
This TM1 model does not use persistent feeders.

Thanks in advance!

Wim

[Duncan P]

Is it possible that someone has added a CubeProcessFeeders call to a TI?

I have seen this message when that function is called. I imagine new is the number of cells that were newly fed as a result of the call, duplicate is the number of cells that were fed more than once or were already fed and that ignored is for cells that were the targets of feeders but that didn't need feeding as they already had normal data in.

[EDIT] On closer inspection it appears that this can be triggered by a non-0 value for MaximumCubeLoadThreads and is not triggered by the TI function call at all. My mistake.

[Wim Gielis]

Thanks Duncan, also for the update !